一个很有意思的Bug

十二月 18, 2007

这个Bug源于昨天凌晨的一次版本升级失败。睡了一大觉后，下午回到公司，重现了这个问题并找到了原因，发现这的确是一个'很有意思的Bug'。

系统在从数据库初始化过程中遇到了问题：在读取数据库数据时，提示ORA-24373错误。手册上对ORA-24373的解释是这样的：
ORA-24373: invalid length specified for statement
Cause: The length specified for the statement is either 0 or too large.
Action: Specify a valid length for the statement.

从错误的提示来看，不应该是数据的问题，但是出于对自己程序的信任，还是首先比对了数据，结果证明了数据是无误的；

看来一定是代码的问题了。首先定位到了返回错误的那个接口OCIStmtPrepare(原型: sword OCIStmtPrepare(OCIStmt *stmtp, OCIError *errhp, OraText *stmt, ub4 stmt_len, ub4 language, ub4 mode))，可是怎么看这块也不该出问题。但从ORA-24373的Cause来看，似乎是传
给OCIStmtPrepare的值不太对劲儿。

我们从数据库读取数据的一般流程：
1、获取符合某一特定条件的某一类数据的条数count；
2、读取count条数据From DB。

为了达到上面的两个目的，我们执行了两次sql操作，分别由两个语句完成，这里不妨成为sql1和sql2。sql1和sql2的内容是在代码里形成的。

其分为两部分：select的字段list和where条件部分；由于where条件部分是动态的，所以每次sql操作之前都是需要先生成sql1和sql2的。

保守的我们认为sql语句的长度是有限的，在我们的代码里我们用了一个宏XX_SQL_MAX_LEN来定义了一条语句内容的最长值，而XX_SQL_MAX_LEN

在我们的系统中被赋予512这个整数值。这样我们很容易得到如下的定义：
char sql1[XX_SQL_MAX_LEN]; //遗憾的是结尾''也被我们算进了XX_SQL_MAX_LEN中了。
char sql2[XX_SQL_MAX_LEN];

一般sql语句的前端的select字段list是固定的，其长度也就是固定的；但是后面的where语句中的条件则是由参数指定。在我们的系统里这个条件很简单，就只有一个索引值(index)。

让我们意想不到的是在我们要读取的那个数据表的操作语句中，select字段list的长度就超出我们预想，达到了508个字节，要知道目前我们还不知道这一事实。我们按照一般数据库操作流程：先读count，再读数据。结果呢？我们读出了若干条数据，然后就在某一条数据上出现了上述错误。这个数据没有什么特殊的，除了其index的值的位数变成了四位之外。

警觉的我们发现：系统在读取index是三位整数的记录时都是没有问题的，偏偏到index是四位整数时才会有问题，而问题偏偏又出在执行sql1上。直觉告诉我们又是内存问题。

分析如下：
sql1和sql2在栈上紧挨着，是否生成sql2的时候污染了sql1的数据呢？我们试图打印出sql1的值，结果发现printf的输出居然是空，这更坚定了内存遭受破坏的想法。遂掰手指头数sql2的长度，发现其长度居然恰好512字节。我们拿一个栈图来说明问题：

栈图

正如上图中所示：sql2的数据多的沿着数据的延伸方向一直越过了边界来到了sql1的境地，在sql1第一个字节上留下一个''就结束了。这就是为什么sql1打印为空的原因。同样由于传给OCIStmtPrepare的参数stmt_len的值为strlen(sql1)，导致stmt_len变为0，也就恰好与ORA-24373这个错误码的说明一致了。这简直太巧了，太不可思议了。不多不少恰好512。

程序员的想当然造就了这一切，就好比千年虫一样，给你我带来麻烦。