rt-thread icon indicating copy to clipboard operation
rt-thread copied to clipboard
verified publisher icon RT-Thread

feat(ulog): add emergency log flush mechanism

Open wdfk-prog opened this issue 1 month ago • 11 comments

拉取/合并请求描述：(PR description)

[

为什么提交这份PR (why to submit this PR)

  • 在系统发生严重故障（例如线程栈溢出、硬件故障中断）时，标准的 ulog_flush() 函数可能无法被安全调用。这是因为常规的日志后端可能依赖于操作系统服务，如互斥锁、信号量、动态内存分配或复杂的文件系统操作，这些服务在中断上下文或系统锁定状态下可能不可用或导致系统彻底崩溃。这使得开发者无法在系统临终前获取到最关键的调试信息。

  • 例如检测线程溢出函数中使用LOG_E打印线程溢出,在启用ULOG+异步输出的情况下将不会显示

  • 就算LOG_E之后加入ULOG_FLUSH,将会打印异常.因为可能挂载了不同的后端输出函数,可能具有异常操作导致一直不断刷新或者输出其他异常情况

  • 开启ULOG+异步输出+文件后端(输出到littlefs文件系统路径下)

  • 线程溢出时,未修复的输出日志如下

[2025/10/30 8:38:23 876]  \ | /
[2025/10/30 8:38:23 876] - RT -     Thread Operating System
[2025/10/30 8:38:23 876]  / | \     5.2.2 build Oct 29 2025 17:11:57
[2025/10/30 8:38:23 877]  2006 - 2024 Copyright by RT-Thread team
[2025/10/30 8:38:24 523] msh />01-01 00:00:00 SFUD: Found a Winbond flash chip. Size is 8388608 bytes.
[2025/10/30 8:38:24 523] 01-01 00:00:00 SFUD: norflash0 flash device initialized successfully.
[2025/10/30 8:38:24 523] 01-01 00:00:00 SFUD: Probe SPI flash norflash0 by SPI device spi10 success.
[2025/10/30 8:38:24 523] 01-01 00:00:00 FAL: Flash device |                norflash0 | addr: 0x00000000 | len: 0x00800000 | blk_size: 0x00001000 |init
[2025/10/30 8:38:24 523] 01-01 00:00:00 FAL: ==================== FAL partition table ====================
[2025/10/30 8:38:24 523] 01-01 00:00:00 FAL: | name       | flash_dev |   offset   |    length  |
[2025/10/30 8:38:24 524] 01-01 00:00:00 FAL: -------------------------------------------------------------
[2025/10/30 8:38:25 739] 01-01 00:00:00 FAL: | filesystem | norflash0 | 0x00000000 | 0x00800000 |
[2025/10/30 8:38:25 739] thread             pri  status      sp     stack size max used left tick   error  tcb addr   usage
[2025/10/30 8:38:25 739] ------------------ ---  ------- ---------- ----------  ------  ---------- ------- ---------- -----
[2025/10/30 8:38:25 739]  
[2025/10/30 8:38:25 739] Firmware name: rtt, hardware version: 1.0, software version: 1.0
[2025/10/30 8:38:25 740] Fault on thread tidle0
[2025/10/30 8:38:25 740] stack_pointer: 0x2000dc50, stack_start_addr: 0x20003e00, stack_end_addr: 0x20003f00
[2025/10/30 8:38:25 740] Error: Thread stack(20003e5c) was overflow
[2025/10/30 8:38:25 740] ===== Thread stack information =====
[2025/10/30 8:38:25 740]   addr: 20003e5c    data: 00000000
[2025/10/30 8:38:25 740]   addr: 20003e60    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e64    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e68    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e6c    data: 20003ea0
[2025/10/30 8:38:25 740]   addr: 20003e70    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e74    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e78    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e7c    data: deadbeef
[2025/10/30 8:38:25 740]   addr: 20003e80    data: 00000000
[2025/10/30 8:38:25 740]   addr: 20003e84    data: 20004100
[2025/10/30 8:38:25 740]   addr: 20003e88    data: 00000000
[2025/10/30 8:38:25 740]   addr: 20003e8c    data: 00000000
[2025/10/30 8:38:25 740]   addr: 20003e90    data: 00000000
[2025/10/30 8:38:25 740]   addr: 20003e94    data: 08023f63
[2025/10/30 8:38:25 740]   addr: 20003e98    data: 08023f62
[2025/10/30 8:38:25 741] ====================================
[2025/10/30 8:38:25 741] =================== Registers information ====================
[2025/10/30 8:38:25 741]   R0 : 00000001  R1 : 20004100  R2 : 00000005  R3 : 09478048
[2025/10/30 8:38:25 741]   R12: 00000000  LR : 08028153  PC : 0802cd5a  PSR: 81030000
[2025/10/30 8:38:25 741] ==============================================================
[2025/10/30 8:38:25 741] Bus fault is caused by precise data access violation
[2025/10/30 8:38:25 741] The bus fault occurred address is 09478048
[2025/10/30 8:38:25 741] Show more call stack info by run: addr2line -e 5axis.elf -afpiC 08023f62 080240a0 080240be 08024156 
[2025/10/30 8:38:25 741] Current system tick: 69
  • https://github.com/armink-rtt-pkgs/CmBacktrace/pull/22
  • 修复后日志如下
2025/10/30 8:52:51 493]  \ | /
[2025/10/30 8:52:51 493] - RT -     Thread Operating System
[2025/10/30 8:52:51 493]  / | \     5.2.2 build Oct 30 2025 08:50:01
[2025/10/30 8:52:51 494]  2006 - 2024 Copyright by RT-Thread team
[2025/10/30 8:54:29 940] msh />01-01 00:00:00 SFUD: Found a Winbond flash chip. Size is 8388608 bytes.
[2025/10/30 8:54:29 940] 01-01 00:00:00 SFUD: norflash0 flash device initialized successfully.
[2025/10/30 8:54:29 940] 01-01 00:00:00 SFUD: Probe SPI flash norflash0 by SPI device spi10 success.
[2025/10/30 8:54:29 941] 01-01 00:00:00 FAL: Flash device |                norflash0 | addr: 0x00000000 | len: 0x00800000 | blk_size: 0x00001000 |init
[2025/10/30 8:54:29 941] 01-01 00:00:00 FAL: ==================== FAL partition table ====================
[2025/10/30 8:54:29 941] 01-01 00:00:00 FAL: | name       | flash_dev |   offset   |    length  |
[2025/10/30 8:54:29 941] 01-01 00:00:00 FAL: -------------------------------------------------------------
[2025/10/30 8:54:33 343] 01-01 00:00:00 FAL: | filesystem | norflash0 | 0x00000000 | 0x00800000 |
[2025/10/30 8:54:33 343] 01-01 00:00:00 FAL: =============================================================
[2025/10/30 8:54:33 343] 01-01 00:00:00 FAL: RT-Thread Flash Abstraction Layer initialize success.
[2025/10/30 8:54:33 343] 01-01 00:00:00 FAL: The FAL MTD NOR device (filesystem) created successfully
[2025/10/30 8:54:33 344] 01-01 00:00:00 NO_TAG: Mount to '/flash' success!
[2025/10/30 8:54:33 344] 01-01 00:00:00 drv.i2c.hw: transmit time out
[2025/10/30 8:54:33 344] 01-01 00:00:00 drv.i2c.hw: transmit time out
[2025/10/30 8:54:33 344] 01-01 00:00:00 drv.i2c.hw: transmit time out
[2025/10/30 8:54:33 344] 01-01 00:00:00 drv.i2c.hw: receive time out
[2025/10/30 8:54:33 344] 01-01 00:00:00 24cxx: 24cxx check failed
[2025/10/30 8:54:33 344] 01-01 00:00:00 kernel.sched: thread:ulog_async stack overflow

你的解决方案是什么 (what is your solution)

  • 为了解决这个问题，本次提交为 ulog 组件引入了一套“紧急日志刷新”机制。该机制允许在不依赖不安全OS服务的情况下，将日志刷新到指定的、被标记为“紧急情况安全”的后端。

主要变更 (Key Changes)

  1. 新增 is_emergency_backend 标志: 在 ulog_backend 结构体中增加一个 rt_bool_t 类型的标志，用于标识该后端是否可以在紧急/故障上下文中被安全调用。
  2. 新增 ulog_emergency_flush() API: 这是一个新的 flush 函数，它会：
  • 在关闭中断的情况下执行。
  • 只调用那些被标记为 is_emergency_backend = RT_TRUE 的后端的 flush 方法。
  • 在异步模式下，它会以“紧急模式”刷新缓冲区，避免了不安全的操作（如 rt_malloc）。
  1. 新增 ulog_backend_set_emergency() API: 允许用户在运行时动态地将某个后端设置为紧急后端。
  2. 将 console 后端设为默认紧急后端: console 后端实现简单，依赖少，是理想的紧急日志输出通道，因此默认开启此标志。
  3. 应用示例: 在 rt_scheduler_stack_check 检测到线程栈溢出后，调用 ulog_emergency_flush() 来确保溢出告警能够被可靠输出。

通过这些变更，系统的可调试性和健壮性得到了显著提升，尤其是在处理和诊断严重系统故障时。

请提供验证的bsp和config (provide the config and bsp)

  • BSP:
  • .config:
  • action:

]

当前拉取/合并请求的状态 Intent for your PR

必须选择一项 Choose one (Mandatory):

  • [ ] 本拉取/合并请求是一个草稿版本 This PR is for a code-review and is intended to get feedback
  • [ ] 本拉取/合并请求是一个成熟版本 This PR is mature, and ready to be integrated into the repo

代码质量 Code Quality：

我在这个拉取/合并请求中已经考虑了 As part of this pull request, I've considered the following:

  • [ ] 已经仔细查看过代码改动的对比 Already check the difference between PR and old code
  • [ ] 代码风格正确，包括缩进空格，命名及其他风格 Style guide is adhered to, including spacing, naming and other styles
  • [ ] 没有垃圾代码，代码尽量精简，不包含#if 0代码，不包含已经被注释了的代码 All redundant code is removed and cleaned up
  • [ ] 所有变更均有原因及合理的，并且不会影响到其他软件组件代码或BSP All modifications are justified and not affect other components or BSP
  • [ ] 对难懂代码均提供对应的注释 I've commented appropriately where code is tricky
  • [ ] 代码是高质量的 Code in this PR is of high quality
  • [ ] 已经使用formatting 等源码格式化工具确保格式符合RT-Thread代码规范 This PR complies with RT-Thread code specification
  • [ ] 如果是新增bsp, 已经添加ci检查到.github/ALL_BSP_COMPILE.json 详细请参考链接BSP自查

wdfk-prog avatar Oct 30 '25 08:10 wdfk-prog

👋 感谢您对 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

  • 设置需排除的文件/目录（目录请以"/"结尾） Set files/directories to exclude (directories should end with "/")
  • 将目标分支设置为 \ Set the target branch to：ulog_emergency
  • 设置PR number为 \ Set the PR number to：10872
  1. 等待工作流完成 | Wait for the workflow to complete 格式化后的代码将自动推送至你的分支。 The formatted code will be automatically pushed to your branch.

完成后，提交将自动更新至 ulog_emergency 分支，关联的 Pull Request 也会同步更新。 Once completed, commits will be pushed to the ulog_emergency 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[bot] avatar Oct 30 '25 08:10 github-actions[bot]

📌 Code Review Assignment

🏷️ Tag: components

Reviewers: Maihuanyi

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

🏷️ Tag: kernel

Reviewers: GorrayLi ReviewSun hamburger-os lianux-mm wdfk-prog xu18838022837

Changed Files (Click to expand)
  • src/scheduler_comm.c

📊 Current Review Status (Last Updated: 2025-11-13 11:17 CST)

  • ⌛ GorrayLi Pending Review
  • ⌛ Maihuanyi Pending Review
  • ⌛ ReviewSun Pending Review
  • ⌛ hamburger-os Pending Review
  • ⌛ lianux-mm Pending Review
  • ⌛ wdfk-prog Pending Review
  • ⌛ xu18838022837 Pending Review

📝 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.

github-actions[bot] avatar Oct 30 '25 08:10 github-actions[bot]

系统异常时，是不是不使用 ulog 打印更好呢？毕竟系统都跑飞了，一些系统状态可能都是不对的，直接用 ulog 导致的连锁反应挺多的，可靠性严重不足。之前的 CMB 日志前端直接用 ulog ，现在看有些草率。

两个小建议：

  • 如果只是想拿到 ulog 异步缓冲区的未日志，那可以直接造个高可靠的迭代接口给到异常环境去取；
  • 异常时，如果想存储更多系统信息
    • 日志后端一定要选择可靠的，最好都不要用文件系统，直接存储到程序状态依赖少的裸介质（裸 emmc 分区、PSRAM 分区、norflash 分区等），下次开机后再进行文件转存
    • 日志前端可以参考 rtdbg.h 造一个精简的给 emergency 专用的接口，和常规 ulog 分开，避免大家混用

armink avatar Oct 30 '25 10:10 armink

系统异常时，是不是不使用 ulog 打印更好呢？毕竟系统都跑飞了，一些系统状态可能都是不对的，直接用 ulog 导致的连锁反应挺多的，可靠性严重不足。之前的 CMB 日志前端直接用 ulog ，现在看有些草率。

两个小建议：

  • 如果只是想拿到 ulog 异步缓冲区的未日志，那可以直接造个高可靠的迭代接口给到异常环境去取；

  • 异常时，如果想存储更多系统信息

    • 日志后端一定要选择可靠的，最好都不要用文件系统，直接存储到程序状态依赖少的裸介质（裸 emmc 分区、PSRAM 分区、norflash 分区等），下次开机后再进行文件转存
    • 日志前端可以参考 rtdbg.h 造一个精简的给 emergency 专用的接口，和常规 ulog 分开，避免大家混用
  1. ulog 直接通过驱动层调用写入函数没什么问题.ulog有做中断可用的逻辑.
  2. ulog会出问题调查下来的话
  • 一个是采用了异步输出,导致系统异常的时候异步线程是无法被切换到进行输出的.这个可以用过flush函数强制刷新解决
  • 另一个是对接了不同的文件后端,有些文件后端的输出是通过文件系统的,这一块是有互斥量无法在中断环境下使用.这个在这个pr中采用了一个变量才区分是否可以在中断或紧急状态下输出到该后端.这个问题也可以解决的了
  1. 所以使用 ulog这个框架是没有问题的.
  2. CMB 日志前端使用ulog没有问题.只是ulog自身还可以选择异步与文件后端等功能,才会触发问题.像CMB的文件备份一样,使用一块单独的分区,不通过文件系统进行写入是可靠的.
  • 问题在于异常时在中断环境下的话,如果存储介质是SPI FLASH这种.目前的驱动是有互斥量,无法在中断环境下使用的.所以提交了另外的pr(https://github.com/RT-Thread/rt-thread/pull/10873)来解决这个问题
  1. 所以综上所述, ulog一直以来反馈的,不生效的问题.其实上是多个条件与使用方式与环境造成的.ulog本身没啥问题
  2. 日志前端可以参考 rtdbg.h 造一个精简的给 emergency 专用的接口，和常规 ulog 分开，避免大家混用
  • 这个的意思是像如下所示这样,提供一个新的日志打印接口?
#define cmb_println(...)               ulog_e(CMB_LOG_TAG, __VA_ARGS__);ulog_flush()

wdfk-prog avatar Oct 31 '25 01:10 wdfk-prog

这个的意思是像如下所示这样,提供一个新的日志打印接口?

是的，总体感觉是要让开发者在使用时，通过 API 接口语义，显性的知道当前哪些接口可以用于系统正常状态或者系统异常状态。

这样，在 ulog 里面不需要考虑一些系统异常的处理，简化 ulog 实现。毕竟 ulog 在设计之初就是考虑了 超轻量级 的这个理念。

armink avatar Oct 31 '25 05:10 armink

  • 增加异常输出后,打印一次线程列表
  • 因为线程溢出的话,查看当前溢出线程的大小,更容易进行调整

wdfk-prog avatar Nov 05 '25 07:11 wdfk-prog

@wdfk-prog CI的报错问题需要修复一下

Rbb666 avatar Nov 13 '25 02:11 Rbb666

@wdfk-prog CI的报错问题需要修复一下

  • 已修复.未考虑到没有开启ULOG的情况

wdfk-prog avatar Nov 13 '25 02:11 wdfk-prog

  • 使用format格式化解决CI错误

wdfk-prog avatar Nov 13 '25 03:11 wdfk-prog

我觉得这个 PR 改动过于复杂，有些违背 ulog 的设计初衷。异常日志，希望不要使用 ulog 进行输出。

  • 异常日志可以选择用ulog或者不用ulog这个是一回事.

  • ulog能不能支持这种情况的调用又是另一回事.

  • 没有这种改动的话,ulog在同步的情况下输出是没问题的;但是在异步开启的情况下是有问题的.

  • 这个pr等于是给用户多了一个选择

  • 另外如果异常日志不使用ulog进行输出的话,想要将异常日志保存到文件系统或者存储介质上的话.得重新做一套,这个更加复杂与不合适吧😢

wdfk-prog avatar Nov 14 '25 02:11 wdfk-prog

回归到问题本身：

  • 1、遇到了什么问题
  • 2、希望得到闭环标准是什么样子

如果问题本身是因为 无法存储 异常日志

  • 根据我的经验，异常环境下执行存储逻辑越复杂，出现问题就越多，反而导致更多的问题
  • 所以从系统可靠性角度出发，要选择更加简单的方式来实现异常日志存储，比如：存储到内存、Flash等逻辑简单的设备，开机再转存。
  • 如果要做抽象，存储和转存代码核心的逻辑可以抽象为软件包，还要简化存储接口最好让 HAL 自行实现，甚至脱离 RTOS 才是最安全的

armink avatar Nov 14 '25 12:11 armink