问题是这样的，我们有一套系统，为客户提供从web访问某台windows的能力，作为管理系统使用。这个系统的后台使用了三四个不同的程序，通过管道通讯。目标设备上有一个组件，要适应2000/2003/2008的32位和64位环境，非常复杂。最近，贝壳将这套系统的目标设备的组件进行了重编译，提供了64位版本。然后测试发现，32位系统不工作了，64位系统正常。

    第一反应是什么？一定是组件有问题？贝壳在服务器上，直接使用连接程序去连接，结果是成功的。这个表明组件应当是正常的，或者部分正常。问题就在web页面到连接程序的过程中某处。

    负责web界面到连接程序的工程师同事接手了下一步排查，他也是一头雾水。系统看来一切正常，连接程序明明可以工作，为什么从web页面调用就会失败呢？而且只有32位会失败。web页面对CPU字长（而且是目标设备的CPU字长）并不敏感阿，这个听起来不合理。

    测试过程中，测试部门的同事偶然的看了一下日志系统，发现了问题。我们的连接程序会写出日志，默认情况下这个日志的属主应当是web.web的，而当时的日志是root.root的，而且权限是644。所以当连接程序被直接调用，当前id是root，就可以连接成功。而连接程序被web调用，当前id是apache，日志写出就会失败，程序就挂了，目标设备会失去反应。

    出现这个错误的原因也很直观，在某次调试后，有人删除了原始的日志，并且直接执行了连接程序。但奇怪的是，同样是连接程序挂掉，为什么64位就可以继续执行呢？我们讨论不出为什么，只有基本猜测，64位设备是2008，rdp服务版本比较高，所以相对健壮。

    所以，实际的错误是两个。一个是日志权限导致的连接程序不工作。另一个是64位下不正常的连接程序依旧可以工作。

    好吧，总结一下这个奇怪的问题中的教训。

1.隔离最小差异。要验证是否是组件升级导致问题，一定要进行旧组件测试，然后再测试新组件。万不可假定旧组件可以正常运行，直接测试新组件，从而将非组件问题带入排查。

2.单元测试隔离。每个部分都要做单元测试，如果测试通过却无法连接，那就是环境问题。再查不出，再检查通讯/调用记录。

3.通讯系统关联错误。当两个程序通过通讯工作，其中一个程序死亡时。另一个程序应当能够检测并且报错退出，而不是出现各种异常反应。

4.日志底线设计。程序一定要写日志，如果日志写不出，就写系统日志，再写不出，设法报全局错误。

    当时客户紧急保修，系统无法继续工作，重启后无效。我们就找了DBA赶快飞去客户那里。客户有两台应用服务器和两台数据库，应用服务器组成热备的态势，数据库组成RAC。数据保存在一个SAN盘阵上，LogFile放本地，ArchivedLog使用备份脚本复制到备份服务器后删除。听起来是挺靠谱的方案，没想到就坏了。

    去了后，客户说暂时恢复了运作。然而我们还是要出具详细的报告，因此赶快去了机房。贝壳第一眼看的东西，就是/var/log。里面的报告是err9，也就是文件读写错误。oracle一切正常，应用发布服务器一切正常。

    这下有点抓瞎了，难不成要出具一份报告说SAN盘阵损坏？可是损坏也得有厂商来维修，说坏得有真凭实据阿。现在SAN一切正常，这个报告怎么写呢？

    说来算巧合，贝壳检查磁盘的时候，顺手打了一句df -h进去，看到磁盘空间已经用掉了80%以上，顺口问了句DBA，如果空间耗尽会如何。DBA说会挂起，和目前状况一致。贝壳顿觉狐疑，是不是空间耗尽呢？是的话，为什么会神秘的恢复呢？

    Oralce的运作非常精巧，也非常复杂。当一条SQL语句执行的时候，先写LOG，然后操作数据，最后再将结果写入LOG。当出现问题需要复原的时候，根据某个时间点的数据备份，和整个运作过程中的所有Log，就可以复原。但是LOG写出的时候量非常大，没有无限的空间给他写阿。所以LogFile的设计是文件循环，当写满一个文件，切换下一个文件。一个文件写满后，就会有一个服务，趁着磁盘空闲，将Log压缩备份为ArchivedLog，然后再将这个文件的状态变为Empty。

    我们的设计，是通过脚本备份ArchivedLog，除去最后一个文件外，复制到备份服务器上，然后删除。但是我们对ArchivedLog的量估计不足，一天清理一次，分配空间只有20G出头。系统开始的时候压力不高，因此绰绰有余。后来压力逐渐升高，这天的操作比较多，ArchivedLog量大了点，导致空间写满。当ArchivedLog空间满之后，备份进程就会报告错误，这就是/var/log下面err9的来历，因此LogFile无法备份出来。当所有的LogFile被循环写满后，SQL执行前试图写入LogFile失败，执行就会失败，然后挂起在那里。这导致了所有应用发布服务器的失效。

    备份脚本的设计是定时和开机结合的，在客户第一次重启设备的时候，已经执行了备份脚本。然而备份动作需要执行相当久，中间客户又重启了几次，导致备份工作进展缓慢。直到半个小时后，第一份ArchivedLog才备份出去。然后清理文件，开始LogFile的备份，大约执行了一个小时多。此时服务就突然恢复了，因为空间问题已经暂时解决。而后是不断的ArchivedLog备份和LogFile的备份的平衡，直到我们到的时候，LogFile已经全部空了，ArchivedLog还没有完成备份。因此我们才能抓到最后的尾巴。

    反过去检查备份脚本的执行记录，基本验证了这个想法，客户也接受了我们的报告，不过还是要责令修改系统——这是后话不提了。

    这个故事里面，至少有几个教训。

1.     对于所有编程时无关紧要的假定值，在开发时可以胡给一个差不多就行，但是上线的时候必须重新分配合理的值。因此必须将这些假定值记录出来，否则从程序中找出假定值来本身就是一个非常困难的事情。

2.     确实运作一下，搞清楚运作方方面面的问题，不要想当然，觉得没问题。就算运作了没问题，在时间的考验前都没人敢保证没事。

3.     一套系统，尤其是大型复杂系统，必须有懂得运维的人员接手管理。检查磁盘IO，CPU压力，内存和磁盘用量，数据量，网络响应速度等等问题。
4.     废物Log不要乱出，太多的Log和没有无异。如果早关注备份脚本的执行记录，就能早找到问题。可是由于量太大，我都是过滤掉了看的。

    第一个故事，是一个传奇的问题。贝壳早在02年的时候，就在家里弄了两台电脑。互相用网线一连，组成局域网打游戏。当时流行的游戏还是Diablo II，当然，这东西的III已经叫了10年，还没出来，接近永远的毁灭公爵。两台机器之间的游戏打的很流畅，一点异常都没有。

    当年文件共享还是有很多问题的，尤其是连续的几个蠕虫，有志一同的使用了windows的samba系统。所以安全上说，贝壳舍弃了windows文件共享，使用ftp方案。当年还流行用ftp开自己的文件资料共享站，贝壳就用雷电自己开了一个。现在基本看不到了，基本都是用网盘或者p2p。问题就出现在这个文件传输上。

    文件传输的速度常常限制在1-3K之间，速度死活上不去。结合Diablo II可以正常工作的事实，贝壳的初步结论是ftp系统问题。然而从外网测试的结果，ftp站点一切正常。那么ftp客户端呢？经过测试，这个客户端软件和配置在外网上访问贝壳自己的站点是正常的。

    那么从表象上看，问题就在客户端所在的机器上了。贝壳检查了机器的网卡和系统驱动，又重装了系统，问题仍旧没有消除——似乎有点奇怪吧。而且推理上说，如果机器有问题，Diablo II也不会运行的如此流畅的。

    好吧，我们揭晓谜底。问题出在两台机器相连的一根网线上。这根网线质量不好，有一根线时通时断。结果导致ip数据包概率性不一致。ip是不管peyload一致性的，但是tcp管阿，结果导致大量的tcp重传。tcp是一种慢启动协议，因此速度死活上不去。

    至于Diablo II可用的问题，则是因为游戏的数据量少，包也小。因此即使慢启动，数据也可以很快重传，导致虽然有问题，却不能很直观的被发现。

    这个问题，直到贝壳无意中更换网线才被发现。但是细究推理，却是合情合理。算是一场灯下黑吧。