一个'莫须有'的BUG

十二月 11, 2006

上周三晚，河南’前线’反馈，河南移动手机用户投诉，经查是话单丢失。查看后的确有蹊跷，按照数据库中录入的原始话单数据来看，这几条记录的确是该生成话单的。之后又有同事发现出现丢话单的问题不仅仅这几条，而是一批一批的。没什么头绪，一夜无话，周四发现每天入库的可生成话单记录数居然比话单多出100万，也就是说我的程序居然少生成了100万话单，按照一条记录1角钱，这也是10万块呀，事情紧迫，问题查找的历程开始。

周四一上班，一封封邮件飞入我的邮箱。我们采取两个办法：
1. 继续分析现网的情况，通过统计数据来找；
2. 在家里这边搭建一套现网环境，来模拟运行，看是否能找出端倪。

还好我们的程序自身带一个统计工具，用来统计生成话单的数量，打开统计文件，核对数据，发现在当天的确生成的话单数要少于从数据库统计的话单数，而且也的确近100万。心头顿生郁闷呀。我们的程序以前的测试过程中从未出现过类似的情况，难道是以前测试的不够彻底，疑惑。

这里简单介绍一下我们的程序，这是一个消息的后处理程序，主要负责生成移动计费中心的计费需要的原始记录文件，我们也叫话单；再有就是把原始记录入库，用来查找统计生成报表。这个程序是一个多进程架构的程序，运行时多个进程互相配合，通过内存队列和文件来做接口，通过灵活的配置衔接两个进程之间的接口，所以说如果配置不当，出现上述现象的可能性还是有的，因此第一我就仔细的查看了配置情况，试图找出可疑之处以解释问题的缘由。可遗憾的是配置都很正确，不存在重复推队列以及推错队列的可能。此时又由于备份的系统输入数据已经被误删除，所以还得等上一些时间，在这段时间我又在系统的一个关键路径上安装的统计工具，我想看看到底是哪出了问题。

我发现事情都喜欢箍堆，这几天自己的私事也不少，周四下午由于私事没能更新代码，周五晚上才更新的代码并同步到现网，等待着运行一段时间后的统计结果。周六上午仍然办私事，中午同事的电话打来说我加的统计数据不准确，赶忙回公司登陆到现网看结果，发现从周六00:00~10:00期间，一共入库约115万条记录，话单也是约115万，也就是说从这个关键路径上流过的数据是约115万，而同事从数据库中统计的数字居然是147万而且居然发现有7万多的数据有重复(数据库没有设置唯一性约束)，没有重复的数据有132万。也就是说我们的程序不仅仅是少生成话单了，而且还重复插入数据了。当时就有些发晕，代码是查了一遍又一遍呀，找不到什么问题。而且统计了原始记录文件，我们系统ftp取来的原始记录文件中的记录数就是约115万左右，和我加的统计工具统计的数值一致，也就是说问题不是少生成话单了，而是多入库和重复入库了。关键路径上的统计数据是115万，那么问题可能出现在后面的模块，统计了最后一步入库操作的输入(文件格式)，发现数据量也是115万，从日志上看也是115万，真是邪了门了。数据库中怎么就无端出现多出来的数据呢，问了同事是否是数据库上某个JOB在自动复制数据，得到的回答是否定的。唯一向数据库中写数据的只有我们的程序。

疑惑和彷徨中发现一个奇怪现象：数据库里重复的数据都是来自数据源主机1的(我们有两台数据源主机)，同事把数据库中重复数据的处理时间Show给我看，我根据那时间，查看了对应时间段的日志，发现一处可疑情况。我们的程序第一个工作就是从数据源主机上取原始数据文件，方式采用ftp get，如果get成功，我们会删除数据源主机上的源数据文件，我从日志中发现其中一处报了一个错误：ftp delete failed, errcode = (22)!，我顿时感觉难道这块是删除失败，重新ftp get导致重复数据的根源吗？我继续往下查发现程序并没有重复取那个文件，也就是说在数据源主机上那个文件已经不存在了。事情蹊跷，把这一现象告诉同事，他问我问什么会这样，我也解释不清楚。

继续查找，仍无头绪，遂决心在各个模块的入口出口加入统计信息，来查找问题所在，当时已经是周五23点30分了，带着疲倦改代码，这时同事突然想到了一点，那就是难道有另外一个一模一样的程序运行在别的主机上？如果真的存在，那么一切上述奇怪现象就都可以解释了。我停掉我们的程序，之后发现数据源主机1上的原始数据文件仍然被不知名程序取走了，我的同事马上逐个查找各台主机，终于在其中一台主机上发现了我们的程序，这个程序是上次测试时启动的，然后忘记停了，而新的程序则部署在另一台机器上。

唉，终于水落石出了。

丢话单：因为另一个程序把原始记录文件抢走，生成话单就放在了它的那台主机上，计费中心并不知道，也就没法获取该话单；
重复入库：两个我们的程序同时取到了原始记录文件，各自入了一份，由于数据库没有唯一性校验，所以导致重复入库。
多入库：还是因为另一个程序把原始记录文件抢走并入库，导致我们的统计工具统计不到该记录数量，所以少于数据库的统计量。

查了半天，费了半天劲，原来居然是一个’莫须有’的BUG，这也提醒了我们以后部署程序上线检查时一定要细心，否则这样的问题查起来很难，如果不是那位同事突然想起来，估计我现在还在苦苦挣扎在这个’莫须有’的BUG上呢。