一个看似无关的日志调用
本地 MCP Server 启动后,tools/list 正常返回,第一次 tools/call 也成功。几分钟后,同一个工具再调用就没有回应了。客户端没有报错,进程还在,CPU 占用接近零。重启服务器后一切恢复,再过一段时间又卡住。
排查时常见的直觉是工具逻辑死循环、锁竞争或者网络问题。但 stdio 传输没有网络。如果工具本身是纯计算,也没有共享状态,这些解释都站不住。真正可疑的是服务端在工具执行前后写出的日志:调试级别打开后,每次调用都会打印参数、耗时和中间结果。客户端只读 stdout 上的 JSON-RPC 消息,stderr 被接到一个从不读取的管道上。
这个场景的关键在于:stdout 和 stderr 是两个独立的管道,客户端只消费其中一个。另一个管道写满后,服务端的写操作会停在系统调用里。工具调用挂起只是这个阻塞的外在表现。
stdio 传输的通道分工
MCP 规范对 stdio 传输的约定很明确。客户端把 MCP Server 作为子进程启动,服务器从标准输入(stdin)读取 JSON-RPC 消息,向标准输出(stdout)写出消息。消息可以是请求、通知、响应或批处理,以换行符分隔,且不得包含嵌入换行符。服务器可以把 UTF-8 字符串写入标准错误(stderr)用于记录日志,客户端可以捕获、转发或忽略这些日志。
这里有两个约束值得单独拎出来。第一,服务器不得向 stdout 写入无效的 MCP 消息。这意味着任何调试打印、启动横幅、第三方库的输出都不能落到 stdout,否则客户端解析 JSON-RPC 时会失败。第二,stderr 的用途被限定为日志,客户端对它有处置权,包括忽略。规范允许忽略,但没有说明忽略的代价。
JSON-RPC 2.0 本身与传输无关,它只定义请求、响应和错误对象的结构。请求带 id 用于关联响应,通知没有 id 且服务端不得回复。MCP 在这套消息格式上叠加了有状态连接和生命周期。stdio 传输把这条连接映射到一对管道上:客户端写 stdin,读 stdout;服务端读 stdin,写 stdout。stderr 不在协议消息路径上,它是旁路。
旁路不等于无代价。在 Unix 类系统上,管道是一个固定容量的内核缓冲区。写端调用 write 时,如果缓冲区剩余空间足够,数据被复制进去并立即返回;空间不足时,写进程进入睡眠,直到读端取走数据腾出空间。这个行为对 stdout 和 stderr 完全一样。区别只在于谁在读。
阻塞是怎么一步步形成的
设想一个本地知识库检索服务器,暴露 search_documents 工具。客户端是桌面 AI 应用,它启动服务器子进程,把 stdout 接到 JSON-RPC 解析器,把 stderr 接到一个管道,但只在进程退出时读取,或者干脆不读。
正常路径下,客户端写入 tools/call 请求,服务端从 stdin 读到,执行检索,把结果作为响应写到 stdout,客户端读到响应,调用完成。日志写入 stderr,管道里积累了几百字节,远未达到容量上限,写操作立即返回。
问题出现在日志量增长时。开启 debug 级别后,每次检索会打印查询词、命中的文档 ID、每个阶段的耗时。一次调用产生几十 KB 日志,连续几十次调用后,stderr 管道的缓冲区被填满。下一次 logger.debug 调用触发 write,内核发现没有空间,服务端进程被挂起。
挂起发生在工具执行的中间位置。服务端还没来得及把响应写到 stdout,就已经卡在日志调用上。客户端继续等待响应,超时之前不会主动取消;即使客户端有超时机制,它看到的也只是“工具执行超时”,而不是“服务端写日志被阻塞”。
更隐蔽的情况是阻塞发生在读取 stdin 之前。如果服务端在启动阶段就打印大量日志,stderr 管道可能在初始化完成前就满了。此时服务端卡在启动日志里,连 initialize 请求都读不到,客户端看到的是握手超时。
flowchart TD
A[客户端启动子进程] --> B[服务端初始化并写启动日志]
B --> C{stderr 管道有空间?}
C -- 有 --> D[服务端读 stdin 收到 tools/call]
C -- 无 --> E[服务端阻塞在写日志]
D --> F[执行检索并写 debug 日志]
F --> G{stderr 管道有空间?}
G -- 有 --> H[写响应到 stdout]
G -- 无 --> I[服务端阻塞在写日志]
H --> J[客户端收到响应]
E --> K[客户端握手超时]
I --> L[客户端工具调用超时]
图中两条失败路径对应两种可观察现象:启动阶段写满导致握手超时,运行阶段写满导致工具调用超时。两者的根因相同,但排查入口不同。
缓冲上限从哪里来
管道容量不是协议规定的,而是操作系统和运行时共同决定的。Linux 上管道默认容量通常是一个内存页的若干倍,具体值随内核版本和配置变化。工程上更可靠的做法是不依赖具体数字,而是把“管道有上限”当作前提。
还有一层缓冲来自语言运行时。Python 的 sys.stderr 在连接到管道时通常是行缓冲或块缓冲,取决于是否检测到终端。C 运行时的 stderr 默认不带缓冲,但很多日志库会自己加一层队列。Node.js 的 process.stderr 对管道是异步写入,内部有流缓冲,超过高水位后会施加背压。这些机制改变的是“多快写满”,不是“会不会写满”。
这里有一个容易误判的点:服务端进程看起来“活着”,因为进程没有被杀死,也没有崩溃。它只是停在某个 write 系统调用上。用 ps 看状态可能是 S(可中断睡眠),用 strace 附加能看到它卡在写文件描述符 2。如果只看进程是否存在,会误以为服务端在正常处理。
容量上限还受读端行为影响。如果客户端把 stderr 接到终端,终端会持续消费,不会阻塞。如果接到文件,文件没有固定容量,写操作直接落盘,也不会阻塞。只有接到管道且读端不消费时,阻塞才会发生。这就是为什么同一个服务器在开发机上正常、在某个客户端里挂起。
日志级别与写入方式的缓解效果
最直接的缓解是降低日志量。把默认级别从 debug 调到 info 或 warn,单次调用的 stderr 输出从几十 KB 降到几百字节,写满管道需要的时间大幅延长。这能推迟问题,但不能消除问题:一个长时间运行的服务器迟早会积累足够多的日志,或者某次异常产生大量堆栈。
第二种做法是让客户端读取 stderr。规范允许客户端捕获、转发或忽略日志,捕获就是把读端接上消费者。消费者可以写入文件、转发到日志系统,或者只在环形缓冲区里保留最近若干行。只要读端持续消费,写端就不会因为缓冲区满而阻塞。这是从根因上解决,代价是客户端需要为每个子进程维护一个读取循环,并处理日志量突增时的内存和磁盘压力。
第三种做法是服务端异步写日志。把日志写入放到独立线程或队列,工具执行路径只做入队,不直接调用 write。这样即使 stderr 阻塞,阻塞的也只是日志线程,工具调用仍能完成。代价是队列本身有上限:队列满之后,要么丢弃日志,要么阻塞入队。选择丢弃意味着故障时可能丢失关键日志,选择阻塞则把问题推迟到队列满的时刻。
| 方案 | 阻塞是否消除 | 日志完整性 | 实现成本 | 适用边界 |
|---|---|---|---|---|
| 降低日志级别 | 否,只推迟 | 保留关键级别 | 低 | 日志量可控、运行时间短的场景 |
| 客户端读取 stderr | 是 | 完整,可落盘 | 中,需读取循环 | 客户端可修改、能承担日志存储 |
| 服务端异步写日志 | 部分,队列满后仍可能阻塞 | 取决于队列策略 | 中,需线程或队列 | 服务端可修改、能接受丢弃策略 |
| stderr 重定向到文件 | 是 | 完整 | 低 | 部署环境可控、有磁盘配额 |
关闭 stderr 或接 /dev/null | 是 | 全部丢失 | 低 | 仅用于排障后的临时运行 |
表格里的“部分”需要展开。异步写入把阻塞点从工具执行路径挪到了日志线程,工具调用不再受影响,但日志线程会卡住。如果队列无界,内存会持续增长;如果有界,满队列时入队操作会阻塞或丢弃。工程上通常选择有界队列加丢弃策略,并记录丢弃计数,这样至少能通过指标发现日志丢失。
还有一种常被忽略的做法:把 stderr 重定向到文件。客户端启动子进程时,把文件描述符 2 指向一个日志文件,写操作直接落盘,不经过管道。这要求部署环境有可写的磁盘路径和配额管理,否则日志文件会无限增长。对于本地桌面客户端,这个方案实现简单,但需要处理日志轮转。
可观测指标与定位步骤
阻塞发生时,客户端侧最直接的信号是工具调用超时,但这个信号没有区分度。需要补充几类指标。
服务端侧可以记录每次日志写入的耗时。正常写入是微秒级,一旦出现毫秒级甚至更长的写入,说明管道接近满。更直接的是在日志线程里记录队列深度和丢弃计数,队列持续增长或丢弃计数非零,说明消费速度跟不上生产速度。
客户端侧可以统计 stderr 管道的未读字节数。如果客户端实现了读取循环,读取速率和积压量都是现成指标。如果客户端不读,至少可以在超时发生时检查子进程状态:进程存在但 CPU 空闲,且 stdout 没有新数据,这是阻塞的典型组合。
定位时可以按以下顺序排查。先确认超时发生在哪个阶段:握手阶段超时指向启动日志写满,工具调用阶段超时指向运行日志写满。再用 strace -p <pid> 附加到服务端进程,观察它是否停在 write(2, ...)。如果停在写文件描述符 2,基本可以确认。最后检查 stderr 的读端:是终端、文件、管道还是 /dev/null,以及读端是否有活跃的消费者。
有一个反直觉的现象值得注意:降低日志级别后问题消失,不代表根因被修复。它只说明日志量暂时没有达到上限。如果服务器需要长时间运行,或者某个工具在异常时打印大量堆栈,阻塞仍会复现。
部署边界与仍未解决的问题
stdio 传输适合本地、单客户端、短生命周期的服务器。客户端完全控制子进程的启动方式,也就能控制 stderr 的处置方式。在这个边界内,把 stderr 接到文件或读取循环是可行的。
边界之外,问题会变形。如果服务器被包装成容器或由进程管理器启动,stderr 可能被接到另一个管道,由上层系统消费。这时阻塞点转移到了上层系统的读取能力上。如果上层系统只读取 stdout,同样的阻塞会以更难排查的形式出现。
协议层面,MCP 规范允许客户端忽略 stderr 日志,但没有要求服务端在 stderr 不可写时降级。服务端无法可靠判断读端是否在消费,也没有标准的背压信号。一个可能的改进是服务端在日志写入超时后丢弃日志并继续执行,但这需要日志库支持非阻塞写入,且丢弃行为本身需要可观测。
在现有规范下,工程上的稳妥做法是:客户端为每个 stdio 子进程启动 stderr 读取循环,服务端使用有界异步日志队列并暴露丢弃计数,部署时避免把 stderr 接到无人消费的管道。这三条都不复杂,但需要同时做到,才能让工具调用不受日志量影响。