上周三晚，河南’前线’反馈，河南移动手机用户投诉，经查是话单丢失。查看后的确有蹊跷，按照数据库中录入的原始话单数据来看，这几条记录的确是该生成话单的。之后又有同事发现出现丢话单的问题不仅仅这几条，而是一批一批的。没什么头绪，一夜无话，周四发现每天入库的可生成话单记录数居然比话单多出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上呢。

最近自己曾经辛苦耕耘过的两个项目同时上线，相关问题也就逐渐暴露出来。工作这两年多时间以后，使我有这样感觉：’测试永远都是不完备的’，有些问题只能在商用过程中发现，呵呵，明确一点啊我不是搞测试的:)

在解决问题过程中的感悟往往是最深刻的，解决问题的过程往往真的像是警察在侦破案件，往往一点点罪犯留下的蛛丝马迹就会让神探们找到线索，并迅速破案。

最近两天一直在一个bug上煎熬着，终于于昨天发现蛛丝马迹并醒悟过来，很有意思的一个bug，和大家一起来分享一下。

这周三我们组的一个同事在现网商用运行的系统上发现我们的程序出现了一个core，对于unix后台服务程序来说，出core是一件很严重的事情，而这个core也直接导致了进程的死锁，消息的积压。

通过gdb调试core发现，问题出在遍历一棵放在共享内存中的B+树，从B+树中取出的地址是一个无效地址，所以当使用memcpy拷贝这个地址上的数据时core出现了。

说到这不能不提及一些背景资料了，在开发这个项目的时候，我们在实现业务需求的时候发现需要部门B+树操作库提供一个完备的遍历接口，可是却发现已有的B+树接口并不提供遍历功能，这显然是库接口的不完备造成的，大家都知道树的遍历是一个特别常见的功能。我们决定对该库进行扩充，添加一个遍历接口；不过，我们在添加接口的时候发现，库内部提供一个叫get_next_key的内部接口，但是该接口的问题在于它返回的下一个key并不是总存储有效数据的。按我们的正常逻辑，如果我们提供一个get_next_key，如果遍历到最后一个有效节点后再继续遍历，则应该返回NOT_FOUND之类的返回值，而这个库中的get_next_key仍然给你返回一个空闲节点，而这个节点中的数据是随机值。了解到这种情况，考虑到时间原因，我定义了一个xx_get_next_key的外部接口，在这个接口实现中我仍然选择使用get_next_key来辅助工作，并且在xx_get_next_key的接口说明中解释到需要业务层控制调用xx_get_next_key的次数。

比如说如果目前B+树中有100个有效节点，那么我调用100次xx_get_next_key均会返回有效节点，如果再100次后继续调用该接口，返回的可能就是非有效数据了。

这样在业务层，我写下了如下代码：
int get_default_xx_info(…) {
 int total = 0;
 int i     = 0;
 xx_get_bptree_msgc(&total);

 for (i =0 ; i < total; i++) {
  调用xx_get_next_key遍历B+树；
 }
}

就是这样的代码在系统运行很长时间后出问题了，通过gdb跟踪到xx_get_next_key的内部实现中，最开始我怀疑是不是对以前的B+树操作库不熟悉，代码调用的不对，后经确认，xx_get_bptree_msgc的实现代码无误。而咋一眼看上去业务层的逻辑也没有问题亚。在查了一个下午之后，仍然没有结果。第二天继续，结合日志和GDB跟踪输出，发现这样的一个很奇怪的现象，而且在我们的分布式系统的两台机器上现象是一致的。

通过日志看出，在调用get_default_xx_info之前，日志打印出来当前B+树中有12610个有效数据节点；而通过GDB跟踪栈上信息，发现B+树中的有效节点是12609个。也就是说我们通过xx_get_bptree_msgc调用得到total值是12610个，而在多次调用xx_get_next_key的间隙时间里，B+树中的节点被其他进程删除了，前面我们提到过我们的B+树是进程间共享的。这样的话，xx_get_next_key使用的约束条件被破坏了，发生了多一次的调用，问题应该就在这。的确，在xx_get_next_key内部执行时是有写锁保证其他进程不会对B+树进行修改的，但是当xx_get_next_key结束一次执行，释放锁资源后，阻塞在该锁上的其他进程对B+树的操作很有可能就发生了，也就是说我们没有保证整个完整遍历过程的事务性。真相大白了。修改也容易了，但是由于库接口的不完备性，使得修改后的逻辑看起来也很别扭，业务层和底层库有交叉了。