六个「看起来是对的」:一次 ESP32 BLE 静默丢包排查
RSIC Lv2

手上有一台 FoloToy AI Passport(TRAE 联名版),ESP32-C3、8MB Flash、没有 PSRAM、240×320 的 ST7789P3 屏。我给它写了个基于 MicroPython 的操作系统(PassportOS),手机通过 BLE 往上推小程序。

一切都能跑。然后有一天,手机 App 里点「刷新列表」——没有任何反应,紧接着提示掉线

一个消失得毫无道理的故障

一开始我以为是个小毛病。但接下来半小时里,这个故障表现出了让人非常不安的性质:

  • 换手机:一样
  • 换电脑、换浏览器:一样
  • 换本地服务器、换线上部署的地址:一样
  • 换命令行客户端(完全不经过浏览器):一样

四组互相独立的变量,故障表现完全一致。

做嵌入式的直觉这时候会告诉你有两种可能:要么是设备端的问题,要么是所有客户端共用的某个东西坏了。但设备看起来好得很——屏幕上明明白白写着「已连接」。

后来我才知道,屏幕上那三个字,是整个排查里第一个骗我的东西。

假象一:屏幕说「已连接」

我把设备拿过来看,屏幕上是正常的主菜单,状态栏写着已连接。

问题在于:ST7789 这类屏在 MCU 停下来之后会保留最后一帧画面。 芯片死了,字还在。屏幕不是状态指示器,是一块会撒谎的画布。

真相是 PassportOS 早就崩了。我的 main.py 顶层有一个兜底的 except,它会把 traceback 打到串口,然后——把整个操作系统停在 REPL 上。设备从那一刻起就是个聋子:界面不动,BLE 事件没人处理,但屏幕还挂着崩溃前的最后画面。

而我当时用的观测手段恰好是:看屏幕。

这里有个更糟的后果。我后来在设备上执行了一段探针代码,想看看堆水位:

1
2
3
4
=== HEAP ===
FREE 152176
ALLOC 1936
NMODS 1 # sys.modules 里只有 1 个模块

NMODS 1 说明根本没有 Python 程序在跑,设备停在裸 REPL 上。可我还是盯着那个「已连接」看了很久,试图从客户端找原因。

教训:观测手段本身会成为故障源。 屏幕会保留残影、日志会被静默吞掉、返回 OK 不代表事情做成了。排查的时候要先问一句:我看到的这个东西,凭什么可信?

假象二:握手成功 = 设备健康

这是整场排查里最贵的一个错误假设。

设备重启之后,我用命令行客户端发 hello

1
2
已连接: 4C:11:AE:32:35:C6
{'name': 'PassportOS', 'os': 'PassportOS', 'apps': 19, 'mtu': 247, ...}

漂亮的回应。我据此判断「设备是健康的,问题在客户端」。

但我漏了一件关键的事:**hellols 走的根本不是同一条代码路径。**

  • hello 的响应是 94 字节 → 一个 BLE 通知就发完了
  • ls(列小程序)的响应是 932 字节 → 要切成 6 片,逐片发

我拿「单片发送成功」当成了「多片发送也会成功」的证据。这两件事在协议栈里是完全不同的路径,而我当时没有任何理由认为它们等价——只是没去想。

1
2
3
hello → NOTIFY #1  len=94   head={        ← 单片,成功
ls → NOTIFY #2 len=181 head=~ ← 第 1/6 片
(后面 5 片,一片都没到)

造一把能看见的尺子

到这一步我意识到,靠现有工具是查不出来的:所有客户端都只告诉我「超时了」。我需要看到每一片

于是写了个只做一件事的探针:订阅通知,把每一片的长度、首字节、尾 12 字节都打出来,再按协议重组,然后**真的去 json.loads**。

结果一跑就见鬼了:

1
2
3
4
5
6
  NOTIFY #2 len=181 head=b'~' tail=b'ck", "s": 15'
NOTIFY #3 len=181 head=b'~' tail=b'n": "muyu", '
NOTIFY #4 len=181 head=b'~' tail=b' "s": 6433, '
NOTIFY #5 len=33 head=b'!' tail=b', "t": "ls"}'
重组完成: 572 字节
✘ JSON 解析失败: JSONDecodeError: Expecting ':' delimiter: line 1 column 365

设备端日志同时显示:

1
[BLE] 响应 932 字节 → 6 片(单包上限 180)

设备说它发了 6 片,客户端只收到了 4 片。 而设备端一次异常都没报

这就是这个 bug 最阴的地方:丢的是中间的片(第 4、5 片),头片和 ! 结尾片都在。重组出来的 JSON 开头正确、结尾正确、中间缺一段——json.loads 报的行号(第 365 字符)会把你引向”解析器有问题”,而不是”数据少了一段”。

我当时盯着那个报错看了很久,第一反应确实是去查客户端的重组逻辑。

真凶:协议栈返回成功,包却没了

原因在 ESP-IDF 的 Bluedroid:TX 队列满的时候,esp_ble_gatts_send_indicate **照样返回 ESP_OK**,而包子被悄悄丢掉。MicroPython 这一层完全看不出异常。

解决办法朴素得让人失望:片与片之间留出时间让控制器把队列排空。

实测 10 ms 不够(还是丢中间片),50 ms 稳:

1
2
3
4
5
响应 932 字节 → 6 片
NOTIFY #2 ~181 #3 ~181 #4 ~181 #5 ~181 #6 ~181 #7 !33
重组完成: 932 字节
✔ JSON 合法,apps=19
带 title 的: 19

同时补上了原本完全缺失的观测能力:现在会打印「响应 N 字节 → M 片」,notify 失败会打印第几片、多少字节、什么异常。原来的代码只做了 self._notify_fail += 1——一个加了但从来没有人读的计数器。

为什么它是”突然坏的”

这条最值得记:它不是突然坏的,是跨过了一个阈值。

响应小于 180 字节时,单片就发完了,一切正常。我不断往设备里加小程序,某一天 ls 的响应超过了 180 字节,从此每次都踩。

阈值型 bug 的伪装特别好:它表现为”以前好好的,突然就不行了”,于是你会去怀疑环境变化、怀疑硬件老化、怀疑最近改的那行无关代码。实际上什么都没变,只是数据量涨过了线。

顺手挖出来的另外几个假象

排查过程中撞见的一堆同类问题,每一个都很短,但每一个都够查半天。

「部署成功」不等于「手机上跑的是新代码」

改完客户端、部署、让用户重试——行为完全没变

两层缓存叠在一起:

  1. Service Worker 的策略是”整站缓存优先 + 后台更新” → 部署后第一次打开必然是旧版
  2. GitHub Pages 对所有文件回 Cache-Control: max-age=600(实测 /app.jssw.js 全都是)

两件事叠起来能连续骗过两次加载。我差点去重写一段本来就正确的重连逻辑。

修法:代码类文件走网络优先(带 cache: 'no-cache' 强制校验 ETag,通常只回 304),图片类保持缓存优先;3 秒超时回退缓存,断网也还能用。另外在界面标题旁加一个版本号——出问题时报一句”我这儿显示 v9”,就能立刻分辨新旧,省掉一整轮瞎猜。这个版本号后来救了我好几次。

gatts_set_buffer(2048) 说的 2048 够不着

做终端功能时需要把一段 Python 源码发到设备上,结果长一点的直接报错:

1
BleakGATTProtocolError: (13, 'GATT Protocol Error: Invalid Attribute Value Length')

我把尺寸一档一档试下去:

1
2
3
4
payload   422 字节 → py          ✓
payload 492 字节 → py ✓
payload 512 字节 → py ✓
payload 522 字节 → 写入被拒 ✗

硬上限是 512 字节。 而代码里明明写着 gatts_set_buffer(cmd_handle, 2048)。那个 2048 是够不着的,实际卡在 Bluedroid 的长写缓冲上。

于是长源码必须分片:客户端按 400 字节切,前几片带 "more": true 只让设备累积,最后一片才真正执行。

sys.stdout 存在,但不可赋值

给终端做 print 捕获,第一版代码是标准写法:

1
2
saved = sys.stdout
sys.stdout = sink

真机上直接炸:

1
AttributeError: 'module' object has no attribute 'stdout'

hasattr(sys, "stdout") 返回的是 **True**——属性存在,只是不可写。这个构建上”重定向 stdout”这条路是死的。

改成往命名空间里注入一个同名 print(遮蔽内置的),不依赖任何构建选项。这条路反而更可靠。

异常对象上没有 __traceback__

终端要报告出错在哪一行,标准做法是走 exc.__traceback__tb_lineno。真机上:

1
tb: MISSING

MicroPython 这个构建的异常对象上根本没有这个属性。

sys.print_exception(exc, file) 能打出完整 traceback。于是我改成从文本里解析 File "<ble-console>", line N,取最内层那一帧。

上一招还有个后续。改完之后真机上仍然只得到一行:

1
NameError: name 'deliberate_error_here' isn't defined

没有文件名、没有行号。我换了个探针直接测:

1
2
3
b = io.StringIO()
sys.print_exception(e, b)
print(repr(b.getvalue()))

输出是完整的:

1
'Traceback (most recent call last):\n  File "<ble-console>", line 2, in <module>\nNameError: ...'

区别在于我传的是自定义对象,而不是原生流。 print_exception 遇到非原生流时,会退化成”只打异常名一行”。

这个坑最危险的地方是:输出看起来是对的。它不是报错、不是空白,是一条格式正确的异常信息——只是恰好缺了终端里最需要的那两条信息(文件名和行号)。

处理故障的代码,本身也会制造故障

挖到后面发现,这一整条链路上还有一处结构性问题:主循环没有错误隔离。

1
2
3
while True:
self.tick() # ← 任何异常都一路穿出 run()
time.sleep_ms(20)

tick() 里任何一处抛异常——一条 BLE 命令处理失败、一次绘制越界、一次分配失败——都会穿出 run(),被 main.pyexcept 接住,整个操作系统停在 REPL 上

而屏幕保留最后一帧,所以设备看起来完全正常。

修法不再只是”把异常吞掉”:

  1. 单次异常记进 /crash.log、打串口、在屏幕上画一屏红底错误页,然后继续跑
  2. 连续失败 20 次才交还给 main.py(那种情况多半显示或内存已经废了)

第 2 条里”在屏幕上画错误页”是关键的一步。屏幕不写东西的话,设备看起来一切正常——这是这个项目里最难查的一类故障,我在这上面绕了很久。

副产品:既然能远程执行代码,那就不用插 USB 了

排查过程中我需要反复”看设备内部状态”。插 USB 开 mpremote 会打断正在运行的系统,而且我人不在设备旁边。

于是有了 BLE 终端:连上设备,手机上直接跑 Python。

1
2
3
4
5
6
7
8
9
>>> gc.mem_free()
73184

>>> x = 41
>>> x + 1
42

>>> print([hex(a) for a in battery.i2c.scan()])
['0x18', '0x63'] # 0x18 = ES8311 音频 codec, 0x63 = CW2017 电量计

它其实是前面所有工作的直接产物:

  • 需要一个 REPL 语义的执行环境(表达式回显、print 捕获、变量跨命令存活)
  • 需要 完整 traceback + 出错那行源码回显——因为终端是一行行敲的,对着行号数第几行很容易数错
  • 需要 长源码分片(就是上面那个 512 字节上限逼出来的)
  • 需要 不依赖任何构建选项的 stdout 捕获(就是 sys.stdout 不可赋值逼出来的)

最终形态(真机输出):

1
2
3
4
5
Traceback (most recent call last):
File "passport/console.py", line 239, in run
File "<ble-console>", line 1, in <module>
TypeError: 'int' object isn't callable
^^^ print(battery.percent())

File "passport/console.py", ... 是终端自己的框架,忽略;File "<ble-console>", line 1 才是你写的代码;^^^ 直接给你出错那行的原文。

有了这个终端之后,”查一下设备现在什么状态”从”插线、开工具、打断系统”变成了”敲一行回车”。

让下一次排查不用重新造尺子

整场排查里,真正解决问题的不是我想通了什么,而是我造出了能看见东西的工具。所以这部分沉淀得最认真:

三个观测工具

工具 解决什么问题
BLE 分片探针 把每一片通知的长度/首字节/尾字节打出来,再按协议重组并真的解析。”设备说发出去了”和”客户端收到了”必须分别验证——中间那一段没人替你看着
纯读取串口脚本 不碰 DTR/RTS、不发控制字符(否则”一开串口就把设备复位”),配合 Ctrl-D 软复位抓完整启动过程
Node 假蓝牙栈 手机上的 Web Bluetooth 没法自动化。用 Node 的 vm 把前端 app.js 真加载起来,喂一套假的 GATT 特征,驱动关键路径

第三个工具是这次最有价值的一件事。前端那段自动重连的逻辑,之前只做过语法检查——而它一次都没有真正执行过。把它跑起来之后,第一次运行就崩了,抓出一个真实缺陷:刷新时链路恰好断开,会留下一个无人处理的 Promise 拒绝。

只做语法检查的改动等于没测过。 这句话我以前只是认同,这次是真被上了一课。

测试与文档

  • test_console.py 44 项:终端的执行环境(表达式/状态/异常/截断),其中专门用假 sys 模块复现”stdout 不可赋值”的真实构建
  • test_protocol.py 41 项:含一条回归,**锁住”多片响应之间必须有间隔”**——防止以后有人把它当无用延迟优化掉
  • pwa_ble_sim.mjs 27 项:在 Node 里真跑前端,含”分片发送长源码”和”上传中绝不重连”
  • known-issues.md 30 条、pitfalls.md 附症状速查表

还有一条文档纪律:API 文档不能照签名写。写终端文档时,我把所有对象在设备上 dir() 出来,再把 13 条示例配方逐条真跑一遍,文档里的输出全是真实回显。

这一条当场就抓到了我自己的错误:battery.percentbattery.millivoltsproperty,不是方法,我写成了 battery.percent(),真机直接 TypeError: 'int' object isn't callable。读代码时 @property 装饰器在 def上一行,我数漏了。

教训清单

按”下次能省多少时间”排序:

  1. 观测手段本身会骗人。 屏幕保留残影、OK 不代表成功、静默吞掉的异常比抛出来的危险得多。先问”我看到的这个凭什么可信”。
  2. 不要用一个成功推断另一个成功。 hello 成功不代表 ls 会成功——它们走的是完全不同的路径(单片 vs 多片)。
  3. 验证链条的每一段。 “设备说它发了”和”客户端收到了”是两件事,中间那一段必须单独取证。
  4. 阈值型 bug 会伪装成”环境变了”。 数据量涨过某个线才开始出问题,看起来永远像”以前好好的突然坏了”。
  5. 只做语法检查的改动等于没测过。 能自动化的逻辑一定要真跑起来,哪怕是给它造一套假环境。
  6. 假绿灯比红灯危险。 一个只扫了部分文件的检查器、一个只打了半截信息的 traceback,都比直接报错更容易把人带偏。
  7. 处理故障的代码本身会制造故障。 兜底 except 把系统停在半个状态、屏幕上不留痕——比崩溃本身更难查。
  8. 给用户一个能分辨版本的抓手。 界面上那个版本号,省下的是一整轮”到底跑的是哪版”的瞎猜。
  9. 文档要跑出来,不要抄签名。 抄签名会漏掉 property / 装饰器 / 构建差异。

最后

有意思的是,回头看这场排查,代码里的 bug 只有一个(缺那个 50 ms 间隔)。剩下的时间全花在错误的假象上:一块会撒谎的屏幕、一个”成功”的握手、一份”没有报错”的日志、一次”部署成功”、一份”写着 2048”的文档。

真凶藏在这些假象后面,而假象的共性是——它们都看起来是对的

代码和文档都在这里:https://github.com/ranshuo-ICer/AI-Passport

手机端可以直接用:https://ranshuo-ICer.github.io/AI-Passport/

 评论