云风的 BLOG

原本系统已经稳定运行了大约 18 个小时，白天都相安无事。项目理论上不算我负责，不过我实现了其中一个模块，已经用到了我们主项目中已有的一个模块，所以我也一直盯着观察运行 log 。

到了半夜，打算烧水冲个澡然后回家睡觉。在等待的空闲时间，一边随便翻着宇宙学的科普书打发时间，一边瞟着自己实现的模块的 log ，突然发现一些异样。

虽然数据包还是合法的，但似乎输入的数据有些不合常理。一下来了精神，想弄清楚是怎么回事。自己检查了系统后，发现系统已经不能正常工作了。由于已经到了零点，办公室就我一个人，想必同事基本都睡了。我决定自己搞定这个问题。

花了点时间翻阅了所有子系统的 log ，追踪到不正常的数据包的流向。由于大部分代码我事前都没有阅读过，对照着代码看有点辛苦。

不正常的表现是，在某种特殊特定情况下，会有一些不正常的数据流过我的系统。但是在 log 上，没有哪个系统曾记录发出这些数据包。了解了数据流向后，我阅读了所有怀疑会出错的子系统的相关代码（中间居然读到两处边际条件下可能出现的例外没有处理对，随手修改掉），都不认为是问题的根本原因。

这个问题其实前天晚上也发生过，可是昨天白天我提出后，每个人都不觉得自己的代码会引起问题。而白天时系统也的确很稳定，这让我很郁闷。作为程序员，我们都相信，既然 bug 出现过，就不可能自动消失，这种情况发生，让人心里有个疙瘩，非常的不爽。

之前有同事甚至联想到是不是系统出了问题，因为在内部测试时从未发生。我本坚信一定是我们自己的实现出了问题，坚持了一天后，到这后半夜神志不清时，差点动摇了。

中间辛苦查错的过程就不详述了。只能说被百般折磨，头晕眼花后，最终在上午和今天上班的同事一起定位了错误根源：

我们是多进程的系统，其中有个子系统拥有一个管理器，管理器以产生子进程的方式引导下级子系统。在 fork 之后，它关闭了自己的标准输出文件句柄。子进程原本没有用 printf 做 log 输出，也就相安无事。可它用到前任一个同事写的一个程序库，在进程异常退出时，可能用 printf 输出一些东西。btw, printf 是 CRT 库中的，在用户空间有缓冲。在进程退出时，会刷新这段缓冲区写到标准输出中。这也是有些使用 fork 的多进程程序有时候会发生重复输出的原因。

因为标准输出已经关闭，但管理器和外部通讯用的 socket 却在 fork 子进程后漏关了。而这个重要的 socket 了复用了标准输出的文件句柄号，这样悲剧就产生了：在几个大的子系统间的通信被一个本该被隔离的进程误插入了一些数据进去，而谁也说不清是从哪来的。而面对几百 M 的 log 文件，偶然发生的这个异常，大部分被过滤扔掉，不会造成太多负面影响。藏在里面的 bug 种子却很久不被人重视。

直到另一个系统处理异常情况的边界条件被触发，测试期没有被覆盖到的分支上的 bug 被引发，它们在一起造成了系统不能正常工作。

ps. 这次事故除了在项目管理和代码管理上给了我一些教训外，能记录下来提醒后来者的技术点是：不要轻易的关闭标准输出，而把它重定向到空设备就可以了。

本来想继续谈谈另外几个 bug 的，写到这里没啥兴致了。问题找到，可以安心过清明了。祝大家节日快乐。