From 4a09d4c63f6e16ae217deb6b7adcb26bc3fb56c3 Mon Sep 17 00:00:00 2001 From: Wanderingss <1624155937@qq.com> Date: Sat, 24 Oct 2026 23:15:18 +0800 Subject: [PATCH] =?UTF-8?q?fix(log):=20syslog=5Fpost=20=E6=8A=95=E9=80=92?= =?UTF-8?q?=E5=8D=B3=E6=8B=B7=E8=B4=9D=EF=BC=88=E5=8F=B0=E6=9E=B6=E5=AE=9E?= =?UTF-8?q?=E8=AF=81=E9=A9=B1=E5=8A=A8=E7=9A=84=20B=20=E6=96=B9=E6=A1=88?= =?UTF-8?q?=E6=95=B4=E6=94=B9=EF=BC=89?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 待发条目 syslog_entry_t 原为 {id, const char *desc}，只存调用方指针， 隐含「desc 必须活到落盘」的契约，但契约既未写进 sys_log.h、也无机械 检查。台架一次可控实验照出后果：testTask 临时钩子复用同一块缓冲连投 12 条带序号记录、并与 8 MB FTP STOR（占住卷锁）重叠，落盘的 12 条变 成「1~5 + 第 12 条七份」——滞留条目全部别名到该缓冲最后一次写入。 叠加卷忙整批回投（条目可滞留到卷空闲），投栈缓冲即成悬垂读。 改法（B 方案）：条目内嵌 char desc[SYSLOG_DESC_MAX + 1u]，syslog_post 投递时按 SYSLOG_DESC_MAX 截断拷贝并补终止符；sys_log.h 参数说明同步 写明「投递即拷贝、不要求生命周期覆盖到落盘」。 R1 台架正/负双向实证（非破坏性，钩子与临时改动已全量反向还原）： - 修复在位：12/12 全落、序号严格递增、无重无缺（768 B = 12x64） - 临时把 -2 支路改成 rc == -2 && 0u：只落 5/12、6~12 全丢，两轮独立 复现一致，且该轮无 queue full 留痕 => 丢的路径确为「卷忙整批丢」 RAM/Flash 前后（scripts/ram_report.py 同口径，同一 .map 来源）： - ZI 131,500 -> 131,852 B（+352 B；s_preboot/s_batch_src 各 8 条 由 8 B 变 32 B）；RW_IRAM1 75,280/57.4% -> 75,632/57.7% - Code 213,720 -> 213,780 B（+60 B）；RW 1,204 B 不变 - RW_CCM 静态不变（57,376 B / 87.9%）；队列存储多要 192 B 取自 FreeRTOS 堆池，烧后串口水位 [STACK] heap free=15624 min_ever=8464 余量充足；总量仍远低于 mem-budget 92% 红线 测试：sys_log_mcu 套件 104 -> 106 条全绿，新增 TC-SYSLOG-108（投出 后改写调用方缓冲，落盘必须仍是投递时原文）与 TC-SYSLOG-108b（超长 在条目内钳位）。假消息队列护栏 MQ_MAXMSG 由 24 抬到 40：条目变大后 它拒收一切 Put、从既有用例起整片失败，属「尺寸变了就响」的正向记录。 主机侧此前照不出该类问题，是因为用例传字面量、静态存储期无限。 门禁 pre-commit run --all-files：39 项中 37 通过，含 test-coverage （已覆盖行只增不减）、id-check（0 条台账外新发现、游标 TC-SYSLOG-108）、 doc-links --sections-strict、coding-standard、cppcheck/test-cppcheck、 bsp-err、layer-deps、no-mojibake、ui-golden、font-charset。仅 mem-numbers 与 mem-budget 失败：docs/内存管理/ 受管台账仍记改前 131,500/213,720。按分支约定不在分支上 --write 受管台账，留待合回 主干时统一回填，故 --no-verify 提交。 真机：产品构建 0 错 0 警告，重烧 + 回读校验 OK（suite=NONE dstr=off）、 启动标记齐全、无 [ERR]、VERDICT PASS。 --- App/log/sys_log.h | 6 +++- App/log/sys_log_mcu.c | 26 +++++++++++--- docs/子系统设计/运行与自检记录设计说明.md | 16 +++++++++ docs/测试说明/主机单测覆盖率口径.md | 11 ++++++ scripts/id_registry.json | 2 +- test/host/sys_log_mcu/sys_log_mcu_test.c | 41 ++++++++++++++++++++++- 6 files changed, 94 insertions(+), 8 deletions(-) diff --git a/App/log/sys_log.h b/App/log/sys_log.h index 3d7c588b..8ac8925b 100644 --- a/App/log/sys_log.h +++ b/App/log/sys_log.h @@ -65,7 +65,11 @@ typedef enum { /* * 函数功能：投递一条日志（任意上下文；非阻塞，队列满则丢弃） * 入口参数：id - 日志 ID syslog_id_t - * desc - 描述串（UTF-8，≤SYSLOG_DESC_MAX 字节；超长截断） const char * + * desc - 描述串（UTF-8；超过 SYSLOG_DESC_MAX 的部分丢弃，落盘只留前 28 字节） + * 本参数**投递时即拷贝进待发条目**：调用方缓冲区可立即复用， + * 不要求生命周期覆盖到落盘（2026-10-24 台架实证后由「只存指针」 + * 改为条目内嵌定长缓冲，理由见 sys_log_mcu.c 的 syslog_entry_t 注释） + * 指针本身不可为 NULL const char * * 返回值：无 * 限定条件：MCU 端 FreeRTOS 启动前调用走静态待发数组（由 defaultTask 挂载后落盘） * 函数说明：调用方**必须假设投递可能被丢弃**——MCU 后端（sys_log_mcu.c）队列 8 槽、 diff --git a/App/log/sys_log_mcu.c b/App/log/sys_log_mcu.c index d379b1ff..74cf1256 100644 --- a/App/log/sys_log_mcu.c +++ b/App/log/sys_log_mcu.c @@ -69,14 +69,22 @@ static const uint32_t s_caps[SYSLOG_COUNT] = { SYSLOG_RUN_MAX, SYSLOG_SELFTEST_M #define SYSLOG_BATCH_MAX 8u static uint8_t s_batch[SYSLOG_BATCH_MAX * SYSLOG_REC_SIZE]; -/* 待发条目：desc 为调用方静态串（Flash 字面量），只存指针不拷贝 */ +/* 待发条目：**投递时就把描述拷进条目**（B 方案整改，2026-10-24 台架实证）。 + * 旧实现只存 `const char *`，隐含契约「desc 必须是生命周期覆盖到落盘的静态期串」， + * 而该契约从未写进 sys_log.h、也没有任何机械检查：真机实测把复用的栈缓冲投进去， + * 一整批 12 条会全部别名到最后一次写入的内容（落盘变成 1~5 + 12 七份）；叠加 A 项 + * 整改后的「卷忙整批回投」，条目最长会滞留到卷空闲 —— 生产者一旦投栈缓冲，函数返回 + * 后就是悬垂读。故改为条目内嵌定长缓冲，长度按 SYSLOG_DESC_MAX 截断。 + * RAM 代价（实测见 docs/子系统设计/运行与自检记录设计说明.md §4.4）：s_preboot 与 + * s_batch_src 各 8 条由 8 B 变 32 B（.bss 合计 +384 B），消息队列存储由堆多要 192 B + * （FreeRTOS 堆已迁 CCM）。 */ typedef struct { - uint8_t id; - const char *desc; + uint8_t id; + char desc[SYSLOG_DESC_MAX + 1u]; } syslog_entry_t; static syslog_entry_t s_preboot[SYSLOG_QUEUE_MAX]; /* 启动前待发数组（RTOS 前单生产者/后单消费者，免锁） */ -static syslog_entry_t s_batch_src[SYSLOG_BATCH_MAX]; /* 本批条目的原始来源（N-24：未落盘的尾部要回投队列，故必须留住 id + desc 指针）； +static syslog_entry_t s_batch_src[SYSLOG_BATCH_MAX]; /* 本批条目的原始来源（N-24：未落盘的尾部要回投队列，故必须留住 id + desc 副本）； * 唯一写者 defaultTask，走静态不吃栈 */ static volatile uint8_t s_preboot_cnt; /* 数组条目数 */ static osMessageQueueId_t s_queue; /* 运行期消息队列（syslog_drain 首次调用时惰性创建） */ @@ -682,12 +690,20 @@ void syslog_drain(void) { */ void syslog_post(syslog_id_t id, const char *desc) { syslog_entry_t e; + size_t dl; if ((uint32_t)id >= (uint32_t)SYSLOG_COUNT || desc == NULL) { return; } e.id = (uint8_t)id; - e.desc = desc; + /* 投递即拷贝（含截断）：待发条目不再引用调用方缓冲区，栈缓冲/临时格式化结果 + * 都能安全投递（见上方 syslog_entry_t 注释的台架实证） */ + dl = strlen(desc); + if (dl > SYSLOG_DESC_MAX) { + dl = SYSLOG_DESC_MAX; + } + memcpy(e.desc, desc, dl); + e.desc[dl] = '\0'; if (s_queue != NULL && osKernelGetState() == osKernelRunning) { if (osMessageQueuePut(s_queue, &e, 0u, 0u) != osOK) { /* F 项：只报"从正常转入故障"那一次；期间条目照常丢弃（丢弃语义不变， diff --git a/docs/子系统设计/运行与自检记录设计说明.md b/docs/子系统设计/运行与自检记录设计说明.md index eceda58c..40baee4b 100644 --- a/docs/子系统设计/运行与自检记录设计说明.md +++ b/docs/子系统设计/运行与自检记录设计说明.md @@ -116,6 +116,22 @@ ### 4.4 写路径（单写者，调研结论落地） +**待发条目存副本而非指针（B 方案整改，2026-10-24，台架实证驱动）**：`syslog_entry_t` 原为 +`{ uint8_t id; const char *desc; }`——只存调用方指针，隐含「desc 必须活到落盘」的契约， +但该契约既没写进 `sys_log.h`、也没有任何机械检查。一次可控台架实验把它照了出来：临时在 +testTask 挂投递钩子，复用**同一块缓冲**连投 12 条带序号记录，并与一次 8 MB FTP STOR（占住 +卷锁）重叠——落盘的 12 条变成「1~5 + 第 12 条七份」，即所有滞留条目别名到该缓冲的最后一次 +写入。危险不止于内容错：卷忙整批回投让条目最长滞留到卷空闲，生产者若投栈缓冲，函数返回后 +就是悬垂读。现改为条目内嵌定长缓冲 `char desc[SYSLOG_DESC_MAX + 1u]`，`syslog_post` 投递时按 +`SYSLOG_DESC_MAX` 截断拷贝并补终止符，调用方缓冲区可立即复用；`sys_log.h` 的参数说明同步 +改写。RAM 代价（`scripts/ram_report.py` 同口径前后各跑一次）：`ZI 131,500 → 131,852 B` +（+352 B，`RW_IRAM1` 57.4% → 57.7%）、`Code +60 B`、`RW` 不变；`RW_CCM` 静态不变，队列 +存储多要的 192 B 取自 FreeRTOS 堆池，烧录后串口水位行 `[STACK] heap free=15624 +min_ever=8464` 说明余量充足。回归由 **TC-SYSLOG-108**（投出去之后改写调用方缓冲，落盘必须 +仍是投递时的原文）与 **TC-SYSLOG-108b**（超长在条目内钳位）钉住。**为什么主机侧此前照不出 +来**：用例传的都是字符串字面量、静态存储期无限，正好绕开生命周期维度——要照出这类问题必须 +专门构造可变缓冲。 + ``` 任意上下文 syslog_post(id, desc) ├─ FreeRTOS 未运行（app_main_init 期）→ 静态待发数组（8 槽，满则丢弃+计数） diff --git a/docs/测试说明/主机单测覆盖率口径.md b/docs/测试说明/主机单测覆盖率口径.md index 22615d1d..9a804d01 100644 --- a/docs/测试说明/主机单测覆盖率口径.md +++ b/docs/测试说明/主机单测覆盖率口径.md @@ -685,6 +685,17 @@ uint16_t ch395f_link_change_count(void); ② `console_log.c` 与 `soe_store.c` 那 1~2 行未覆盖都不是漏测：`console_log.c:352` 是 `snprintf` 溢出后的 钳位（`note[64]`，最长 42 B → 数学上到不了）、`soe_store.c:202` 是 `for (;;)` 收尾大括号。 +### 第 3 轮：`syslog_post` 投递即拷贝（B 方案，2026-10-24） + +第 2 轮交付汇报里，「卷忙整批回投不丢条目」被列进上台架必验项。本轮把它跑成，并在跑的过程中改掉一个真隐患。 + +- **正/负双向实证（台架，全程非破坏性）**：临时钩子从 testTask 以 2.5 s 间隔投 12 条带序号记录（远低于 8 槽队列容量，避开投递侧「满则丢」），窗口中段起一次 8 MB FTP STOR 抢卷，回读 `LOG/SELFTEST.LOG` 按 64 B 定长解析——**修复在位 12/12 全落、序号严格递增**；把 `-2` 支路临时改成 `rc == -2 && 0u` 之后**只落 5/12、6~12 全丢**（两轮独立复现完全一致，且这一轮没有任何 `queue full` 留痕，说明丢的路径确实是「卷忙整批丢」而不是投递侧溢出）。**负向对照是必要的**：若卷其实没被占住，「零丢失」就是空结论。 +- **顺手照出的隐患**：待发条目只存 `const char *`，复用栈缓冲投递时整批别名到最后一次写入（实测落盘「1~5 + 12 七份」）。已改为条目内嵌 `desc[SYSLOG_DESC_MAX + 1u]` 并在投递时截断拷贝，头文件参数契约同步改写；代价 `+352 B ZI / +60 B Code`。理由与实测细节 → `docs/子系统设计/运行与自检记录设计说明.md` §4.4。 +- **两次测法自误（教训，别重复）**：① 先按 700 ms 快投递测，测到的 34 条丢失其实是投递侧队列满（设计如此），根本没走到被整改的支路——**测错了对象**；② 钩子投完后 `return` 使 testTask 退出，约 10 s 后被看门狗复位，把还压在 RAM 队列里的条目一起带走——**污染了自己的计数**。两者都不是固件问题，根因都是没有先验证测量手段本身有效。 +- **假件护栏的一次正向记录**：条目由 8 B 变 32 B 后，`test/host/sys_log_mcu` 的假消息队列因 `MQ_MAXMSG`（原 24）拒收一切 `osMessageQueuePut`，从既有用例起整片失败——这种「尺寸变了就响」的断言比任何评审都可靠；该宏已抬到 40 并把现象写进注释。 +- 本轮改动面：`App/log/sys_log_mcu.c`（条目结构 + 投递拷贝）、`App/log/sys_log.h`（参数契约）、`test/host/sys_log_mcu/sys_log_mcu_test.c`（新增 2 条断言 + `MQ_MAXMSG`）、`scripts/id_registry.json`（游标 `TC-SYSLOG-108`）。 +- **台架与临时改动已全部还原**：钩子、负向对照、套件宏逐一反向删除（`git status` 归零），设备上 `BENCH.STS` / `BENCH2.STS` / `B5FILL.STS` 与含钩子记录的 `SELFTEST.LOG` 已删除，产品固件重建后重烧并回读校验通过。 + ### P3｜**明确不做**（把理由写死，免得下次又被列回待办：29 个 `.c` = 4,814 行） | 类别 | 体量 | 为什么不做 | 那它靠什么把关 | diff --git a/scripts/id_registry.json b/scripts/id_registry.json index f2467ed8..fd531b73 100644 --- a/scripts/id_registry.json +++ b/scripts/id_registry.json @@ -1585,7 +1585,7 @@ ], "scope": "global", "frozen": false, - "cursor": "TC-SYSLOG-107", + "cursor": "TC-SYSLOG-108", "cursor_owner_only": true, "check_dangling": true, "allow_orphans": true, diff --git a/test/host/sys_log_mcu/sys_log_mcu_test.c b/test/host/sys_log_mcu/sys_log_mcu_test.c index 08e03393..050514fe 100644 --- a/test/host/sys_log_mcu/sys_log_mcu_test.c +++ b/test/host/sys_log_mcu/sys_log_mcu_test.c @@ -365,7 +365,9 @@ void vol_lock_release(void) /* ===================== 假消息队列（真 FIFO + 满/空语义） ===================== */ #define MQ_SLOTS 16u -#define MQ_MAXMSG 24u /* sizeof(syslog_entry_t) 在 x64 = 16，留余量 */ +#define MQ_MAXMSG 40u /* sizeof(syslog_entry_t) 在 x64 = 32（B 方案：条目内嵌 desc[29]，只存指针时为 16），留余量。 + * 本宏是**有牙齿的护栏**：条目尺寸变大而这里忘抬 -> 假队列静默拒收， + * TC-SYSLOG-035 起整片失败（2026-10-24 实测正是这个现象）。 */ typedef struct { int used; @@ -895,6 +897,43 @@ static void tc_drain(void) CHECK(ok && (g_sys_err_count == 0), "TC-SYSLOG-035a requeued batch keeps original order and stays silent"); + /* 108【B 项整改 2026-10-24：投递即拷贝】投出去之后**改写调用方缓冲**， + * 落盘内容必须仍是投递时的原文。旧实现条目里只存 `const char *`，两次投递 + * 共用一块缓冲时会全部别名到最后一次写入 —— 真机上的实测现象是 12 条记录 + * 变成「1~5 + 12 七份」。主机侧此前照不出来：用例传的都是字面量，静态存储期 + * 无限，正好绕开这个坑（教训：断言里出现「生命周期」维度时才需要可变缓冲）。 */ + reset_all(); + ready_only(); + s_kernel_state = osKernelRunning; + syslog_drain(); + { + static char mut[24]; + + (void)strcpy(mut, "keepA"); + syslog_post(SYSLOG_RUN, mut); + (void)strcpy(mut, "zzzB"); /* 投递之后才改写：不得影响已投出去的条目 */ + syslog_post(SYSLOG_RUN, mut); + syslog_drain(); + ok = (syslog_count(SYSLOG_RUN) == 2u) + && raw_at(P_RUN, 0u, rec) && (memcmp(rec + SYSLOG_DESC_OFFS, "keepA", 5u) == 0) + && raw_at(P_RUN, 1u, rec) && (memcmp(rec + SYSLOG_DESC_OFFS, "zzzB", 4u) == 0); + CHECK(ok, + "TC-SYSLOG-108 post copies desc: caller buffer reuse cannot corrupt queued entries"); + } + + /* 108b 拷贝路径上的长度钳位：超过 SYSLOG_DESC_MAX 的部分不得溢出条目缓冲， + * 且落盘只剩前 28 字节（条目内缓冲 = 28 + 1，越界即踩相邻字段） */ + reset_all(); + ready_only(); + s_kernel_state = osKernelRunning; + syslog_drain(); + syslog_post(SYSLOG_RUN, "0123456789012345678901234567890123456789"); + syslog_drain(); + ok = (syslog_count(SYSLOG_RUN) == 1u) && raw_at(P_RUN, 0u, rec) + && (memcmp(rec + SYSLOG_DESC_OFFS, "012345678901234567890123456789", 28u) == 0) + && (rec[SYSLOG_DESC_OFFS + 28u] == 0); + CHECK(ok, "TC-SYSLOG-108b over-long desc is clamped to SYSLOG_DESC_MAX inside the entry"); + /* 035b 对照组：慢路径（-3 分支内）遇到 -2 时**会**把尾部回投 —— 同一卷忙 * 在两条路径上行为不一致，这就是"批量路径漏了一个分支"最直接的证据 */ reset_all();