wandering1/STM32F4-Base
1
0
Fork 0
Code Issues 29 Pull Requests 1 Actions Packages Projects 2 Releases Wiki Activity

v2-on-ui #4

Merged
wandering1 merged 497 commits from v2-on-ui into master 2026-11-02 04:07:13 +08:00
Conversation 0 Commits 497 Files Changed 910
+1283 -8
9 changed files with 1283 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files
Showing only changes of commit b1280e3cd1 - Show all commits
.dsh/skills/serial-boot-test/SKILL.md
+3 -1
View File
@@ -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=<n>` 是显式逃生口，不是默认）。子串 `--required` 不能用于"可能丢行首/被插字节"的行。来龙去脉与固定动作见本仓 `docs/测试说明/启动日志原子性复验流程.md`。
交互式串口操作（open/send/log/wait-idle/status 等）不属于本 skill——
**用 `serial-assistant` skill**。
.dsh/skills/serial-boot-test/scripts/run_boot_test.py
+20 -1
View File
@@ -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=<n>' 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 收口，否则就又回到假绿。
.dsh/skills/serial-boot-test/scripts/verify_log.py
+232 -4
View File
@@ -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=<n>"): 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] <iso> ...'), 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=<n>' 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__":
docs/测试说明/boot_log_data/20261026_bench23_flash_boot_log.txt
+164
View File
@@ -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
docs/测试说明/boot_log_data/20261026_bench23_recheck_verdicts.txt
+44
View File
@@ -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)
docs/测试说明/boot_log_data/20261026_bench23_reset_only_boots_r1_r4.txt
+676
View File
@@ -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
docs/测试说明/boot_log_data/README.md
+36 -1
View File
@@ -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_<stamp>.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 判据
docs/测试说明/启动日志原子性复验流程.md
+107
View File
@@ -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] <ts>` / `[+Nms]`）后**整行** `^REGEX$` 必须命中；同时报告"含该式最长字面串但未整行命中"的邻居行 = 交错特征 | 单点插字节即失配；邻居不得静默 |
| `…@@LEN=<n>` 后缀 | **显式**钉该行字节长度 | 长度属于**某一份像**的属性；默认不钉，否则无辜改动就假红（实测同一份像 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 <boot_log.txt> `
--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-<ID>-<sha> <sha>` + `mklink /J <wt>\.venv <main>\.venv`；
建树后 `git -C <wt> 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 <NAME>`（**不带** `--bench-pass`）即可释放；
`--bench-pass` 会先读 `_wt/.state/<NAME>.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`
docs/测试说明/自动化测试流程.md
+1 -1
View File
@@ -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` |
## 判定标准