一次诡异的控制台刷屏排查:当 Python 标准库偷偷多了一行 print

最近遇到一个很迷惑的问题：运行Python项目时，后台控制台一直输出类似这样的内容：

dfd4437dfd4819dfd1531dfd517dfd892...

一开始看起来像是某个业务日志、调试输出。但最后发现，真正的原因非常离谱：

Python 标准库的 json/decoder.py 被改了，里面多了一行：

print('dfd' + str(len(s)))

也就是说，只要程序调用 json.loads()，控制台就会输出一行 dfd + JSON 字符串长度。

这篇文章记录一下完整排查过程，以及这类问题以后怎么定位。

现象

启动后端服务：

pdm run uvicorn app.main:app --host 127.0.0.1 --port 8000

控制台在 Uvicorn 正常启动日志之前，就开始输出：

dfd4437dfd4819dfd1531dfd517dfd892dfd403...INFO:     Started server process [30729]INFO:     Waiting for application startup.INFO:     Application startup complete.

服务启动后，请求接口时也继续输出：

ounter(lineounter(lineounter(linedfd27dfd1576INFO:     127.0.0.1:50737 - "GET /api/manage/agents HTTP/1.1" 200 OK

这个现象有几个关键特征：

1. pdm run dev 会出现。
2. 直接运行 uvicorn app.main:app 也会出现。
3. 输出发生在 Uvicorn 启动日志之前。
4. 每次请求也可能触发新的输出。

这说明它不像普通业务接口里的日志，更像是“模块导入阶段”或“底层公共函数”在输出。

第一轮排查：先排除项目源码

最自然的思路是全局搜索：

rg -n "dfd|print\\(|console\\.log|logger\\." .

结果没有找到任何业务代码里写了 dfd。

这一步很重要。很多时候我们会被现象带偏，以为是某个服务、Redis、请求日志。实际上，如果全仓库没有 dfd 字面量，就说明它可能来自：

1. 依赖包。
2. Python 标准库。
3. 虚拟环境里的文件。
4. 本机环境被污染。
5. 运行时动态执行的代码。
   

第二轮排查：利用启动时机判断范围

一个非常关键的观察是：

dfd4437dfd4819...INFO:     Started server process [30729]

dfd... 出现在：

INFO: Started server process

之前。

这说明问题大概率发生在：

import app.main

这一阶段。

也就是说，还没开始处理 HTTP 请求，甚至 FastAPI 应用还没完全启动，某些 import 过程中就已经触发了输出。

所以，与其继续猜哪个接口有问题，不如直接追踪：到底是谁在写 stdout。

关键方法：猴子补丁追踪 stdout

写一个临时脚本，把 sys.stdout.write 包一层。如果发现输出以 dfd 开头，就打印调用栈。

临时脚本大概是这样：

import sysimport traceback_stdout_write = sys.stdout.writedef wrapped(text):    if str(text).startswith("dfd"):        _stdout_write("\n--- DFD stdout write stack ---\n")        traceback.print_stack(limit=20, file=sys.stdout)    return _stdout_write(text)sys.stdout.write = wrappedimport app.main

然后运行：

pdm run python tmp_trace_dfd.py

调用栈直接暴露了真相：

File ".../json/__init__.py", line 346, in loads    return _default_decoder.decode(s)File ".../json/decoder.py", line 340, in decode    obj, end = self.raw_decode(s, idx=_w(s, 0).end())File ".../json/decoder.py", line 356, in raw_decode    print('dfd' + str(len(s)))

最终定位到这个文件：

/opt/homebrew/Cellar/python@3.12/3.12.9/Frameworks/Python.framework/Versions/3.12/lib/python3.12/json/decoder.py

里面真的有一行：

print('dfd' + str(len(s)))

这就解释了所有现象。

根因

json.loads() 是 Python 程序里调用频率极高的基础函数。

后端启动时，会加载配置、解析 schema、读取依赖包里的 JSON 文件。请求进来时，也会解析请求体、响应、数据库 JSON 字段、依赖内部数据。

所以一旦标准库的 JSON decoder 被加了调试输出，整个应用就会到处刷屏。

这里的 dfd4437 其实不是 ID，而是：

'dfd' + str(len(s))

也就是当前被解析的 JSON 字符串长度。

例如某次解析的 JSON 文本长度是 4437，就输出：

dfd4437

解决方式

有两种方式。

第一种，直接删除那一行：

print('dfd' + str(len(s)))

位置是：

/opt/homebrew/Cellar/python@3.12/3.12.9/Frameworks/Python.framework/Versions/3.12/lib/python3.12/json/decoder.py

第二种，更稳妥，重装 Python：

brew reinstall python@3.12

然后验证：

cd backendpdm run python -c "import json; json.loads('{}')"

如果没有任何 dfd... 输出，就说明恢复正常了。

这次排查的几个经验

第一，不要只盯业务代码。

如果日志在服务启动日志之前出现，优先怀疑 import 阶段、依赖包、标准库、运行环境。

第二，看到奇怪输出时，先判断它是 stdout 还是 logger。

这次不是 Python logging，也不是 Uvicorn access log，而是裸 print()。所以查 logger 配置没有意义。

第三，猴子补丁 stdout 是定位裸 print() 的利器。

当不知道是谁在 print() 时，可以临时包住：

sys.stdout.write

发现目标输出就打印调用栈。这个方法对定位第三方包、标准库、本地环境污染都非常有效。

第四，标准库也可能被污染。

我们通常默认 Python 标准库是可信的。但本地开发环境里，手滑编辑、调试残留、错误脚本替换，都可能让标准库变脏。

第五，虚拟环境不等于完全隔离。

项目用的是 .venv，但 .venv 里的 Python 解释器仍然引用 Homebrew 安装路径下的标准库。所以 Homebrew Python 标准库被改了，虚拟环境也会受影响。

总结

这次问题表面上看是后台控制台莫名刷 dfd数字，实际原因是 Python 标准库 json.decoder 被加了一行调试输出。

最终定位路径是：

现象：后台持续输出 dfd数字↓搜索项目源码：没有 dfd↓观察启动时机：Uvicorn 启动日志前就出现↓判断发生在 import 阶段↓猴子补丁 sys.stdout.write↓打印调用栈↓定位到 json/decoder.py↓删除调试 print 或重装 Python

这类问题最怕的是一直在业务逻辑里绕圈。真正有效的办法，是回到程序运行机制本身：谁写了 stdout？什么时候写的？调用栈在哪里？

抓住这三个问题，答案通常就不远了。