Skip to content

feat(ulog): support output the calling function, file and line - #11987

Open
ymj0440 wants to merge 4 commits into
RT-Thread:masterfrom
ymj0440:fix-ulog-output-file-line
Open

ymj0440 wants to merge 4 commits into
RT-Thread:masterfrom
ymj0440:fix-ulog-output-file-line

Conversation

@ymj0440

@ymj0440 ymj0440 commented Nov 5, 2026

Copy link
Copy Markdown
Contributor

Description

This PR implements the feature requested in #7724: support outputting the calling function name, file name and line number in ulog.

Three independent switches are introduced so that users can freely decide which context information to output, avoiding overly long log lines:

  • ULOG_USING_OUTPUT_FILE: prepend the calling file name
  • ULOG_USING_OUTPUT_FUNC: prepend the calling function name
  • ULOG_USING_OUTPUT_LINE: prepend the calling line number

When all switches are disabled (the default), the output is completely unchanged, so existing behavior is preserved.

Example output with all switches enabled:

[main.c:42] app_entry(): this is a debug log!

How to test

Enable the switches in menuconfig (RT-Thread Kernel -> Enable ulog) or define them in rtconfig.h, then use the LOG_D/LOG_I/LOG_W/LOG_E APIs as usual.

Notes

  • The existing ulog APIs (ulog_output, ulog_e/i/w/d) are kept unchanged for backward compatibility. The new function ulog_output_ctx() is only used by the LOG_X macros.
  • Verified with gcc -fsyntax-only under three configurations (all switches off / all on / only function name) and checked the macro expansion contains the expected __FILE__ / __FUNCTION__ / __LINE__ values.

Fixes #7724

Add three independent switches (ULOG_USING_OUTPUT_FILE/FUNC/LINE) so that
users can freely decide whether to prepend the calling file name, function
name or line number to the log message when using the LOG_X API. These
switches are disabled by default, keeping the output unchanged.

Signed-off-by: ymj0440 <[email protected]>
@github-actions

github-actions Bot commented Nov 5, 2026

Copy link
Copy Markdown

👋 感谢您对 RT-Thread 的贡献!Thank you for your contribution to RT-Thread!

为确保代码符合 RT-Thread 的编码规范,请在你的仓库中执行以下步骤运行代码格式化工作流(如果格式化CI运行失败)。
To ensure your code complies with RT-Thread's coding style, please run the code formatting workflow by following the steps below (If the formatting of CI fails to run).


🛠 操作步骤 | Steps

  1. 前往 Actions 页面 | Go to the Actions page
    点击进入工作流 → | Click to open workflow →

  2. 点击 Run workflow | Click Run workflow

  • Use workflow from 保持默认分支(通常为 master)
    Keep the default branch (usually master) in Use workflow from
  • 在 branch 输入框填写 PR 分支 fix-ulog-output-file-line
    Enter PR branch fix-ulog-output-file-line in the branch field
  • 设置需排除的文件/目录(目录请以"/"结尾)
    Set files/directories to exclude (directories should end with "/")
  1. 等待工作流完成 | Wait for the workflow to complete
    格式化后的代码将作为独立提交推送至你的分支。
    The formatting changes will be pushed to your branch as a separate commit.

完成后,提交将自动更新至 fix-ulog-output-file-line 分支,关联的 Pull Request 也会同步更新。
Once completed, commits will be pushed to the fix-ulog-output-file-line branch automatically, and the related Pull Request will be updated.

如有问题欢迎联系我们,再次感谢您的贡献!💐
If you have any questions, feel free to reach out. Thanks again for your contribution!

@github-actions

github-actions Bot commented Nov 5, 2026 •

Copy link
Copy Markdown

📌 Code Review Assignment

🏷️ Tag: components

Reviewers: @Maihuanyi

Changed Files (Click to expand)
  • components/utilities/Kconfig
  • components/utilities/ulog/ulog.c
  • components/utilities/ulog/ulog.h
  • components/utilities/ulog/ulog_def.h

📊 Current Review Status (Last Updated: 2026-11-08 07:46 CST)


📝 Review Instructions

  1. 维护者可以通过单击此处来刷新审查状态: 🔄 刷新状态
    Maintainers can refresh the review status by clicking here: 🔄 Refresh Status

  2. 确认审核通过后评论 LGTM/lgtm
    Comment LGTM/lgtm after confirming approval

  3. PR合并前需至少一位维护者确认
    PR must be confirmed by at least one maintainer before merging

ℹ️ 刷新CI状态操作需要具备仓库写入权限。
ℹ️ Refresh CI status operation requires repository Write permission.

@Rbb666

Rbb666 commented Nov 5, 2026

Copy link
Copy Markdown
Member

三个独立开关符合 #7724 的需求,不过当前实现还有三处问题需要修正。以下基于提交 8aa4a23e。

  1. 原有的静态日志级别过滤失效了。 ulog.h:70–73 将 LOG_E/W/I/D 直接改为调用 ulog_output_ctx(),绕过了 ulog_e/w/i/d 中对 LOG_LVL 和 ULOG_OUTPUT_LVL 的判断。两个级别都设为 ERROR 时,原来的 LOG_D("value=%d", expensive_side_effect()) 会被预处理掉,这版仍会调用函数并求值参数。三个新开关全部关闭时也一样,和描述中的“默认行为不变”不符。这里需要保留原有的条件编译,全关时建议直接走原来的调用路径。

  2. 格式字符串被提前截断,会丢掉本来能放下的日志。 ulog.c:864–868 先把原始格式串复制到 fmt[ULOG_LINE_BUF_SIZE],再展开参数。但格式串可能比输出结果长。例如缓冲区为 128 字节,格式串由 30 个 %02x 组成,传入 1 到 30:模板长 150 字符,输出只有 90 字符。原版能完整输出,这版在三个开关全关时只剩前 25 个值,末尾还多出一个 %。应该截断格式化后的结果,不能先截断格式串。

  3. 文件名里的百分号会被当成格式指令。 ulog.c:864、874 把上下文直接拼进 fmt,随后又交给格式器解析。源码路径允许包含 %。用 file="dir%u/test.c"、format="value=%u"、参数 11, 22 验证,实际得到的是 [dir11/test.c] value=22,文件名吃掉了正文的参数。如果只传正文所需的一个参数,就会读取不存在的变参;路径里出现 %s 时还可能错误解引用。上下文应作为普通文本写入缓冲区,正文继续使用完整的原始格式串。

第一项用 GCC 预处理验证过;后两项用该提交的 ulog_output_ctx() 和同版本 tiny 格式器做了最小运行验证。建议补上这些回归用例,再确认默认配置和各开关组合的行为。

@github-actions

github-actions Bot commented Nov 5, 2026 •

Copy link
Copy Markdown

MemBrowse Memory Report · Explore what changed →

hpmicro-hpm5301evklite

  • ILM: .fast +16 B (+0.1%, 23,728 B / 131,072 B, total: 18% used)
  • XPI0: .fast +16 B (+0.0%, 76,764 B / 1,048,576 B, total: 7% used)

k230

  • SRAM: .bss +61,608 B, .data +1,080 B, .eh_frame +22,440 B, .sbss +48 B, .srodata.cst8 +24 B, .stack +8 B, .text +103,968 B (+15.7%, 1,395,268 B / 60,682,240 B, total: 2% used)

qemu-virt64-aarch64

  • Code: .eh_frame +32 B, .text +624 B (+0.1%, 1,009,692 B)

wch-ch32v208w-r0

  • FLASH: .text +208 B (+0.1%, 159,888 B / 491,520 B, total: 33% used)

No memory changes detected for:


Catch memory regressions in CI with MemBrowse. Free for open source.

@Rbb666 Rbb666 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

复核提交 8aa4a23eac3833c8846801218df75f1da69414ea,此前评论中的三个问题仍存在,请修复后再合并。

  1. [P1] 保留原有静态日志级别过滤。 ulog.h 第 70–73 行 直接调用 ulog_output_ctx(),绕过 ulog_e/w/i/d 对 LOG_LVL 和 ULOG_OUTPUT_LVL 的条件编译。即使三个新开关全部关闭,被过滤日志的参数仍会求值。已核对 Nuvoton CI 失败日志:M460 驱动原本被 ERROR 级别过滤掉的 LOG_I 现在参与编译,暴露 nu_usbd.address_tmp 未声明错误。请修复宏的过滤行为,而不是仅修改该驱动以绕过这次失败。

  2. [P1] 上下文必须作为普通文本处理。 ulog.c 第 864–874 行 将文件名等上下文拼入格式串,随后再次解析。源文件路径含百分号时会消耗正文的变参:使用 file="dir%u/test.c"、正文 "value=%u"、参数 11, 22,实际得到 [dir11/test.c] value=22。只有一个正文参数时会读取不存在的变参,路径含 %s 时还可能错误解引用。请直接写入上下文文本,正文保持使用原始格式串。

  3. [P2] 不要在展开参数前截断格式串。 新增的 fmt[ULOG_LINE_BUF_SIZE] 先截断模板,会丢失原本能完整输出的数据。例如 30 个 %02x 的模板长 150 字符,但展开 1–30 后只有 90 字符,原本能放入 128 字节缓冲区;当前实现提前截断模板,输出不完整,并可能留下残缺格式指令。请限制最终输出长度,而非原始模板长度。

本轮使用提取的当前函数和主机格式器复核了参数副作用、百分号路径及长模板问题。请补充新开关全关、各开关组合、静态级别过滤及上述格式化场景的回归验证。

另请将标题和提交信息改为仓库要求的方括号前缀,例如 [ulog] 支持输出调用文件、函数和行号;验证说明应通过 menuconfig/pyconfig 生成 BSP 的 rtconfig.h,不要建议手工修改。

@BernardXiong BernardXiong left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

结论:暂不建议合并,前两项为阻塞问题。

1. [P1] 静态日志级别过滤被绕过 / Static level filtering bypassed

ulog.h#L70-L73

LOG_E/W/I/D 直接调用 ulog_output_ctx(),绕过了 ulog_def.h 中 ulog_e/w/i/d 的 (LOG_LVL >= ...) && (ULOG_OUTPUT_LVL >= ...) 条件编译。即使三个新开关全部关闭,被过滤日志的参数仍会被编译和求值,代码体积和运行时开销都会增加。

这也是 Nuvoton CI 失败 的直接原因:drv_usbd.c 定义了 DBG_LEVEL DBG_ERROR,第 442 行的 LOG_I 原本被过滤掉,现在参与编译,暴露了 nu_usbd 未声明。正确的修法是恢复宏的过滤逻辑,而不是去改该驱动掩盖问题。

2. [P1] 上下文被拼进格式串 / Context merged into the format string

ulog.c#L864

rt_snprintf(fmt, sizeof(fmt), "[%s] %s", ctx_buf, format) 会把 __FILE__ 等上下文再次当作 printf 格式串解析。若路径含 %,例如 file="dir%u/test.c"、正文 "value=%u"、参数 11, 22,实际输出 [dir11/test.c] value=22;路径含 %s 时还可能解引用错误指针。

建议把 [file:line func()] 作为普通文本直接写入输出缓冲(或给 ulog_voutput 增加上下文字段),正文继续使用原始 format。

3. [P2] 展开前截断模板 / Format template truncated before expansion

ulog.c#L836-L837

每次日志调用都在栈上分配两个 ULOG_LINE_BUF_SIZE 缓冲;模板在展开前就被截断,长模板会丢数据,甚至留下残缺的 %。三个开关全关时应直接回退到 ulog_output();开启时应限制最终输出长度,而不是原始模板。

4. [建议]

  • ulog.h#L59 使用 C99 的 __func__ 代替 GNU 扩展 __FUNCTION__。
  • 标题和提交信息建议按仓库约定加 [ulog] 前缀。

1. Keep the compile-time log level filtering. LOG_X still expands to
   ulog_e/w/i/d when all three switches are disabled, and the new
   ulog_x_ctx macros share the same LOG_LVL/ULOG_OUTPUT_LVL guard, so
   logs filtered out at compile time do not evaluate their arguments.
2. Format the message before truncation. The original format string is
   always used in full; only the formatted result is limited by
   ULOG_LINE_BUF_SIZE, so a long template with a short output is no
   longer cut.
3. Assemble "[context] message" as plain text and pass it to the
   formatter through an "%s" format, so '%' characters inside the file
   name or the message are never parsed as format specifiers.

Verified with gcc -fsyntax-only (all off / all on), macro expansion for
the level filtering case, and runtime cases for a long format template
and for '%' inside file names.

Signed-off-by: ymj0440 <[email protected]>
@ymj0440

ymj0440 commented Nov 6, 2026

Copy link
Copy Markdown
Contributor Author

Thanks @Rbb666 for the careful review. All three issues are fixed in a2e8d01b:

  1. Static log level filtering: LOG_X now expands back to ulog_e/w/i/d when all three switches are disabled, and the new ulog_x_ctx macros are defined inside the same #if (LOG_LVL >= ...) && (ULOG_OUTPUT_LVL >= ...) guard as the original ones. Logs filtered out at compile time expand to nothing, so their arguments are not evaluated. Verified by preprocessing with LOG_LVL=3 and ULOG_OUTPUT_LVL=3: LOG_D(...) disappears, LOG_E(...) keeps using ulog_output().

  2. Format string truncated in advance: ulog_output_ctx() now formats the message first with rt_vsnprintf(body_buf, sizeof(body_buf), format, args). The format string is always used in full; only the formatted result is limited by ULOG_LINE_BUF_SIZE. Verified with a 30-specifier %02x template (format string ~150 chars, output ~90 chars): all 30 values are printed.

  3. Percent sign in the file name: the [context] message text is now assembled as plain text and passed to the formatter as an %s argument, so % inside the file name or the message is never parsed as a format specifier. Verified: file="dir%u/test.c", format="value=%u", arg 11 gives [dir%u/test.c:10 f()] value=11; file="dir%s/test.c", format="name=%s", arg "bob" gives [dir%s/test.c:10 f()] name=bob.

When all three switches are off, ulog_output_ctx() takes the original ulog_voutput() path directly, so the default output is byte-for-byte unchanged.

I also added the regression checks above as verification steps; if you prefer, I can turn them into a test case in the repository.

@BernardXiong

Copy link
Copy Markdown
Member

CI 的 Check File Format and License 在 head a2e8d01b 仍失败,属代码格式问题,不是环境或基础设施故障:

  • components/utilities/ulog/ulog.h:77-80:LOG_E/W/I/D 宏
  • components/utilities/ulog/ulog_def.h:74-105:ulog_d/i/w/e 及 *_ctx 宏

失败日志:https://github.com/RT-Thread/rt-thread/actions/runs/42181815149/job/127772930166
请用仓库锁定的 clang-format 22.1.8 处理这两个文件后重新推送;其余 CI 检查已通过。


The Check File Format and License job still fails on head a2e8d01b (code formatting, not infrastructure): clang-format violations in ulog.h:77-80 and ulog_def.h:74-105. See the job log above. Please run the repo-pinned clang-format 22.1.8 on both files and push again; the other checks pass.

Format the LOG_X and ulog_x_ctx macro definitions in ulog.h and
ulog_def.h with the repo-pinned clang-format 22.1.8, fixing the
'Check File Format and License' CI job.

Signed-off-by: ymj0440 <[email protected]>
@ymj0440

ymj0440 commented Nov 7, 2026

Copy link
Copy Markdown
Contributor Author

Thanks @BernardXiong. Both files are now formatted with the repo-pinned clang-format 22.1.8 (pip install -r tools/ci/requirements-format.txt) in 8fa52fc2; only the macro definitions touched by this PR changed.

Re-verified after formatting:

  • all switches on: LOG_D expands to ulog_output_ctx(<level>, LOG_TAG, __FILE__, __FUNCTION__, __LINE__, ...)
  • all switches off: LOG_D goes back to ulog_output(<level>, LOG_TAG, RT_TRUE, ...), and compile-time filtered levels still expand to nothing (arguments not evaluated)
  • gcc -fsyntax-only passes for both all-off and all-on configurations

@BernardXiong BernardXiong left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

复核 head 8fa52fc2:格式检查已通过,三个开关独立配置、关闭时保留原有静态日志级别过滤的设计也成立。发现一处边界问题:

[一般] ulog_output_ctx() 可能把未初始化的栈内容拼进日志

components/utilities/ulog/ulog.c:849-860 中:

n = rt_snprintf(ctx_buf + pos, sizeof(ctx_buf) - pos, "%s", file);
pos += (n > 0 && n < (int)(sizeof(ctx_buf) - pos)) ? n : (sizeof(ctx_buf) - pos - 1);

当 rt_snprintf() 返回 0(例如调用方传入空字符串 file)或负数时,pos 会被直接推到 sizeof(ctx_buf) - 1;随后 ulog.c:893 的 rt_memcpy(out_buf + 1, ctx_buf, pos) 会拷贝 ctx_buf 中未初始化的内容并输出。经 LOG_X 宏传入的 __FILE__ 不会为空,但 ulog_output_ctx() 是头文件中公开的 API,空字符串即可触发,属于潜在栈信息泄漏。

建议只在 n > 0 时推进 pos;n >= remaining 时取 remaining - 1,或先把 ctx_buf[0] = '\0' 初始化。

建议:ULOG_FUNC_INFO 使用 __FUNCTION__ 属于编译器扩展,可考虑改用标准 __func__ 以提升可移植性。


Reviewed head 8fa52fc2. Format checks now pass, and the independent-switch design (falling back to the original static level filtering when all three switches are off) is sound. One edge case:

[Medium] ulog_output_ctx() can copy uninitialized stack data into the log

At ulog.c:849-860, when rt_snprintf() returns 0 (e.g. an empty file string) or a negative value, pos is advanced to sizeof(ctx_buf) - 1; ulog.c:893 then copies pos bytes from the uninitialized ctx_buf into out_buf and emits it. The LOG_X macros never pass an empty __FILE__, but ulog_output_ctx() is a public API in ulog.h, so the empty-string case is reachable and can leak stack contents.

Suggested fix: only advance pos when n > 0 (use remaining - 1 when truncated), or initialize ctx_buf[0] = '\0' first.

Only advance `pos` when rt_snprintf() returns a positive value, so that
an empty file name or function name can no longer push `pos` to the end
of the buffer and make the following memcpy pick up uninitialized
stack bytes. Initialize ctx_buf[0] as well.

Also use the standard __func__ instead of the compiler extension
__FUNCTION__ for ULOG_FUNC_INFO, as suggested.

Verified: empty file -> pos stays 0; normal case -> 'main.c:42
app_entry()'; a 95-byte file name is truncated safely to the buffer.

Signed-off-by: ymj0440 <[email protected]>
@ymj0440

ymj0440 commented Nov 7, 2026

Copy link
Copy Markdown
Contributor Author

Thanks @BernardXiong for the careful review. Both points are addressed in 2820068a:

  1. [Medium] uninitialized stack data: pos is now advanced only when rt_snprintf() returns a positive value, and ctx_buf[0] is initialized to '\0'. An empty file/func therefore keeps pos == 0 and takes the no-context path (ulog_voutput() with the original format), so nothing uninitialized is ever copied. Verified: empty file -> pos == 0; file="main.c", line=42, func="app_entry" -> pos == 21, prefix [main.c:42 app_entry()]; a >127-byte file name is truncated to pos == 95, still inside the buffer.
  2. __FUNCTION__ -> __func__: ULOG_FUNC_INFO now uses the standard __func__.

The changed lines pass clang-format -style=file --dry-run --Werror with the repo-pinned 22.1.8.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

ulog支持打印调用所在的函数,文件名和行数

3 participants