对错误 -22 的追踪 - 博客 - 第二场高尔夫

这是一篇关于在嵌入式软件中搜索并最终修复一个难以找到的 bug 的线性回顾。

背景

  • 在 Tweede golf 为使用 nRF9160 微控制器的客户工作,用 Rust 和 Embassy 构建固件,之后客户接手维护和开发。
  • 半年后客户联系,生产固件中出现奇怪问题,编译后多数时间运行正常,但代码中微小变化会导致向服务器发送数据常返回Error::NrfError(-22),编译器版本和优化设置也会影响该问题。

初始探索

  • 错误难以复制,客户提供了展示该行为的代码分支。
  • 怀疑是编译器 bug 或代码中触发未定义行为(UB)的坏代码,虽 Rust 语言能防止此类问题,但代码中有不安全代码,尤其是与调制解调器通信的 C 代码块。

调制解调器工作原理

  • nRF9160 是双核芯片,第一核用户可用,第二核是运行自身调制解调器固件的调制解调器核心,用户无法直接操作,与调制解调器核心通信的协议是专有,通过libmodem库及配套头文件通信,需提供nrf_modem_os.h头文件中的函数,Rust 中使用nrf-modem crate 作为libmodem的包装器。

回到问题,错误 -22 是什么

  • 错误来自libmodem的调用,nrf-modem crate 定义了许多自定义错误,该错误未被预期的错误变体覆盖,而是直接返回错误代码,查找 Nordic 提供的错误代码定义,发现 22 对应NRF_EINVAL(无效参数),但调用函数的文档未提及此错误,阅读相关 POSIX 文档也未找到解释,说明得到了不可能的错误。

接下来怎么办

  • 若 bug 对编译器版本敏感,可能是编译器 bug,项目锁定在 2023-12-26 nightly 版本,尝试找到新版本看问题是否不再出现,但过程中遇到“调制解调器监狱”(连接基站次数过多被限制连接),最终发现 2024-02-05 和 2024-02-06 版本问题仍存在,且差异过大无法审查。

为什么是错误 -22

  • 若为编译器 bug 难以在剩余时间找到,继续研究错误本身,Nordic 论坛虽难获取帮助,但决定查看反汇编,发现调试信息仍存在,nrf_send函数主要调用nrf_sendtonrf_sendto函数进行一些状态检查、准备数据、将 RPC 请求放入共享内存、等待 RPC 响应然后返回,错误处理通过比较和分支指令实现,发现错误 106 对应NRF_EAFNOSUPPORT(地址族不支持),在汇编中找到错误 22 被加载到r0的地方,是sock_sockaddr_len_is_valid函数导致,nrf_sendto posix api 有相关有效错误,Nordic 工程师未意识到此错误会传播到nrf_send函数,怀疑是内存 corruption,但调试困难,在连接和发送函数之间可能存在内存 corruption 导致检查失败。

继续新视角

  • Wouter 开始乐观地尝试解决问题,发现sock_sockaddr_len_is_valid函数本身没问题,但其仅在sockaddr参数不为 null 时被调用,而连接函数已检查过,所以怀疑有其他地方返回错误,最终在 RPC 调用中发现错误 6 翻译为 22,推测是无效输入导致,RPC 发送数据过程包括将数据缓冲区复制到共享 TX 内存、构造 RPC 数据等,调试仍受调制解调器监狱影响,通过 dump 共享内存内容寻找线索,但未获太多信息。

长度为 0 意味着什么

  • 比较工作版本和错误版本的共享内存状态,发现工作版本中 RPC 有有效指针和长度,错误版本中为 null 指针和长度 0,在调用nrf_send函数的包装器中,通过安全 Rust 代码获取缓冲区并传递给nrf_send函数,看起来正常,但添加black_box后问题消失,怀疑是优化导致问题,比较两个二进制文件困难,工具不佳,在 MIR 和 LLVM-IR 中也发现更多 dereferences,通过dwex查看调试信息后发现是black_box导致捕获缓冲区方式改变,增加了额外的间接层,解释了 extra dereferences,但仍不知为何此方法有效。

几乎准备放弃

  • 长时间未取得进展,已花费约 20 天,没有明确方向,考虑采取 brute-force 方法但受调制解调器监狱限制,寻找修复问题的特定 PR,最终找到rust-lang/rust#118960,引入local_waker到异步上下文,但调查后发现只是改变了程序行为,未修复问题。

最后努力

  • 仍有信心找到问题根源,尝试 mocking 调制解调器和获取 watchpoint 工作,mocking 调制解调器容易但结果令人失望,无法重现问题;Wouter 很快使 watchpoint 工作,通过 watchpoint 找到 rpc 长度从 44 被缩短为 0 的原因,是数据写入共享内存时长度被缩短以适应最大大小,但共享内存大小已配置为 8kB,怀疑是libmodem认为大小为 0,通过 watchpoint 发现问题出在nrf_modem_init函数中,调制解调器 init 函数有指针参数,内部使用指针到配置结构的字段,init 完成后配置被丢弃,指针无效,程序版本不同导致随机写入影响 tx 区域大小值,这与栈布局有关,作者的 wrapper 存在类似问题,Nordic 的初始化方式也可能存在问题,作者已在 Nordic 的 DevZone 论坛开单但未更新文档,作者认为若libmodem用 Rust 编写就不会出现此问题,呼吁停止用 C 创建新项目。
阅读 15
0 条评论