|
2005年，当时我为公司自动测试组维护一套辅助库。这套库封装了设备通讯以及各种命令返回信息的识别、分类以及错误监控等功能；之后，做自动测试的同事就不再需要关注这些细节，只要说清楚“我这一步期望看到什么”，这套库就可以帮他分析返回结果、输出测试通过与否之类信息并自动生成测试报告。 这套库由一种很小众的语言写成，这种语言叫TCL，你可以认为它是一种shell脚本，所以继承了命令行写批处理的各种怪异风格；同时它还提供了类似python的进阶功能，比简单的shell script稍微强大一些——这就在水平不高的自动化测试人员和相对强大的语言能力之间取得了平衡。 Bug并不是我搞出来的。我写程序追求0 Bug，实际上一年大概也就出过1个Bug——本来想和另一位同事较劲，他写了两年0 bug，结果没赢过他。 因为对0 Bug的追求，我对语言本身的坑比较敏感；组内遇到疑难Bug，最终也往往会交给我。 这个Bug是多年前提交的，之后一直断断续续有人遇到；但当你下决心追查时，又常常几个月都遇不到一次。 做过debug的业内人士都知道，一个bug症状越明显、发作越频繁，它就越好处理；最怕的就是这种一年半载不出现一次的。 后来这个Bug就挂给了我。不要求排除，不限时间。毕竟好多年了都没人能抓到。就是要我上点心，留意点，能抓到最好，免得测试组总过来找。 我大致看了看，完全没有头绪。相关代码4、5万行都可能是有的；bug描述也极为模糊、混乱，完全没有方向。 解决这个bug的过程是极其曲折的；其中很多前置是在其他相关/无关项目中无意间完成的。这些前置渐渐填平了通向问题的鸿沟。 在这个bug之前，我得到了另一个“积年老Bug”。这个Bug也是偶发，时有时无，让人摸不着头脑。同样是积压了好多年，没人能解决——当时这个库已经有二十多万行代码，从中找一个时有时无的奇葩Bug，完全是大海捞针。 而在此之前，我为这个支撑系统做了个模拟运行系统。 这是因为，所有这些测试代码都要在网元上运行；而这些网元中，性能比较猛的，两台就足够东南亚那些小国全国使用的——从它的电话通讯到电脑网络，全都由这个设备提供支持。 这种设备当然不可能多。测试组想开始测试，就得提前申请；然后如果测试用例有Bug，就把大量机时浪费掉了。而我们写的代码，测试起来就更难了。 所以，我搞了个模拟系统：你下发命令，我从数据库找出记录下来的、对应的命令返回给你，这样你就不需要在真机上调试了。 借助这个模拟系统，我们就可以把bug出现前测试组日志里记载的命令返回“喂”给程序逻辑。这果然使得Bug重现了。 这东西本来给其他同事负责。他们观察了很久，仍然找不到问题原因。最终，这个问题还是到了我手里。 通过到处插日志打印语句，我发现这个问题是因为“命令返回的结果信息丢失”引起的。但测试组证明，命令结果的确返回了。 调查卡到了这里，再也进行不下去了。 我并没有放弃。有空就琢磨。 终于有一天，通过反复对比正常执行过程和出错误的执行过程，我发现出错时，程序多了一条report。 网元返回的信息包括命令返回、alert、report。alert出现就得记录并报错（除非本就预期有这么一条alert），而report一般可以无视，记录然后丢弃就是。所以没人注意这一点。 我知道，测试时网元负荷极低，而且先做过初始化。因此每次执行应该都差不多；这里多个report，很可能就隐含着什么…… 我开始仔细观察程序和网元的交互记录，发现那里的命令返回似乎有些不对。 命令返回有几百行，其中一列是时间；正常来说，时间应该是2019-10-31 18:21:22、2019-10-31 18:21:22、2019-10-31 18:21:23、2019-10-31 18:21:24……这样子一路排下来。 但那段数据，它的时间却是2019-10-31 18:21:22、2019-10-31 18:21:23、2019-10-31 18:21:21、2019-10-31 18:21:22、2019-10-31 18:21:23……也就是在秒这个级别存在乱序（实际上是在毫秒级别存在乱序/跳跃，即时间格式为2019-10-31 18:21:22.456 2019-10-31 18:21:22.567这样，其中某些行组之间存在2、300毫秒的跳跃）。 我按时间连续性把数据分割，发现它的输出是每几条到十几条为一组，组内顺序正常，组间乱序/跳跃；但把这些组挑选、拼接，可以得到两组数据，组内时间顺序良好、间隔均匀。 这说明，这些数据可能是两个命令的返回，不知怎么混到了一起。这种混淆使得命令输出格式错乱，这才使得程序把命令返回识别成了report。 于是我找测试组询问，果然，他们测线路备份切换之类功能，所以需要同时控制两个网元；命令在程序中是顺序下发的，间隔可能只有若干毫秒。 心里有了底，我开始观察程序所在目录，果然在里面找到个dat文件；用十六进制编辑器打开，里面果然是网上传来的原始报文信息，二进制格式。报文格式是 网元编号:信息 。 再检查相关代码，很显然，这是因为网元编号被底层通讯模块丢弃了，只把文本信息返回给了上层；这就使得上层无法区分信息来自哪个网元。平常这样做还没有问题；但遇到同时连接多个网元且需要同时检查多个网元返回、且返回信息还比较多时，数据就乱了。 这个东西太基础。它和上层关系太过紧密，修改它影响太大；而且底层通讯模块的源码已经丢失…… 于是，我尝试用字符串分析的办法来恢复它。鉴于不同命令返回格式不同、数据各异，我用程序尝试识别每个字段的数据类型，然后再检测它是否为有序内容。 我把这类列叫“索引列”，索引列有三种，一种是1、2、3这样的数字编号，另一种是网元编号这样一整个都是某个固定数字/字符的，还有就是年月日时分秒这样的时间信息；它们可能同时全部出现，但也可能只出现其中一种，甚至全都没有。 当识别出索引列之后，我就把顺序不乱、时间不跳变的若干行视为一个整体；然后像分析单词的“编辑距离”一样，寻找一种使得数据整体上“编辑距离”调整最小的方案，把混淆的数据分隔开。 因为一组数据可能有多个索引列，按照不同索引列拆分的方案还可能不一样。因此我不得不遍历各种拆分方案，寻找综合最优的那种方案…… 这是个挺复杂的程序。它超出了TCL的能力范围——它的确能工作，而且没有出错时消耗很小；但一旦出错，它需要一分多钟才能恢复。 总之，虽然我还是把这个程序写出来了、而且的确能自动识别并纠正这种问题；但性能消耗太严重，不是可用于生产的正常解决方案。 我们终于还是决定重写底层通讯模块，修改通讯约定。这的确会引起底层代码的大量更改，但毕竟范围还算可控，而且不需要付出恐怖的性能代价。 另外，我还把解决这个问题的思路、经验等总结下来，写了一篇文章。这篇文章被公司文档库收录（但忘了是A级还是B级了）。 以上种种，先后占用了我一个月时间（寻找bug根源和用tcl尝试排除bug）和另外若干人的若干月时间（新底层模块的需求分析和代码编写）。其中新通讯模块的设计我也有参与。 在解决上面那个bug的尝试中，我发觉TCL这种语言先天不足；一旦程序逻辑复杂，它那变量无需声明、变量无类型等等对初学者来说不可多得的“优点”就成了致命缺陷。你不得不付出比C/C++之类“正规语言”多得多的努力去跟踪去区分数据类型；为了避免错误，我不得不把数据类型也“打包”进数据，然后在程序入口写代码分辨它——尤其是，这些数据类型还是动态的，是从输入数据识别出来的；不结合输入谁都不知道某个数据在某个时刻会是什么。 这使得代码几乎无法静态分析；而测试用例很难覆盖每一条执行路线——不要忘了，这个程序“吃”进去的数据是多变的，你几乎不可能列出所有情况。 这使得我产生了一个想法。那就是，我要给它增加一些功能，把专业语言的core dump、变量先声明后使用等等功能搞出来，使得出现类似高危行为时可以得到提醒甚至直接对相关不良行为报错。 TCL号称一切都是字符串。你甚至可以把系统库函数/运算符/关键字都给rename掉，然后自己写一个替代品。 这给了它的用户极大的自由度。比如iTCL就是用命名空间模拟的面向对象语法——这种语言仍然是面向过程的；但你可以自己定义一个class关键字（实质上是一个过程），把它变得和一个真正的面向对象语言几乎一模一样。 我盯上的是它的过程/函数声明关键字proc。 在这种语言里，你声明一个函数fun，格式就是 proc fun(arg) { #body } 它看似一个关键字；但TCL里一切都是字符串，因此这个proc实质上是个函数，它接受函数名、参数列表、函数体三个参数…… 我把系统的proc改名叫_sys_proc，自己写了个proc；这样当用户声明一个函数/过程时，他的声明将以字符串格式先传给我；我可以做一些修改，把一些逻辑插进用户编写的代码中，然后再把修改后的代码传给_sys_proc。 通过这种方式，我接管了TCL的一切；然后修改了它的异常/返回流程，识别出“用户未捕捉的异常”（我记录了每个函数在某次被调用时、在调用链上所处的层级；接近顶层尚未捕获就会影响到当前测试用例、当前测试套甚至引起整个程序过早退出，这些都是要记录的）。 现在，当你的程序出错时，如果你通过异常处理程序解决了问题、允许程序继续执行了，那么我就不做任何动作；但如果你没有处理异常、使得测试失败甚至程序退出，那么我就能在执行下一条语句之前把整个调用链打印出来——从函数调用关系到每个函数的局部变量内容、再到异常传递路径，巨细靡遗。 这个设计相当于函数返回时会多执行几条语句，把局部变量等信息保存在内存中；只要程序不崩溃，那么这些信息就自动丢弃；而一旦程序要崩溃，它就会写到磁盘文件中——我还搞了个日志滚动机制，最多只记录最近十次崩溃信息，并不会无限侵占磁盘空间。 通过这个东西，付出微不可察的时间代价，我给所有TCL程序增加了core dump功能。这显然是个重大利好。 尤其是，如果你不想付出这个代价，那么不要import DebugTools即可——我把它做到了debug工具库中，你导入这个库，它就立即起作用；你不导入，那就不需要付出任何代价（时间太久，这个库的名字我已经记不清了。不过按我的风格，应该会这样命名）。 因此，它一写出来就受到了欢迎，马上就加进了新发布版中。 几个星期又这样过去了。 有了这件利器，我便通知相关项目组，让他们在自己的项目开头import DebugTools；如果那个偶发故障出现，把目录下的error.01.log等文件发给我。 刚好测试组有个测试任务。没几天，故障重现了。 拿到调用栈信息之后，花了几天时间就很容易的追查到了根源。 这是当年实现时的疏忽：在某个函数中，他们声明了一个局部变量，这个变量和同一命名空间的另一个变量名字极为相似，但命名风格（首字母是否大写之类）和其他代码不太一致。因此我判断当时他们是为了规避不同作用域的命名冲突才这样命名的。 但到了后面，他们仍然习惯性的用了“正常”的命名（也可能是选错了编辑器自动提示选项）。这就相当于丢开局部变量，用了命名空间的外部变量；但从上下文看，这里就不应该碰外部那个同名变量。 用伪码表示大概是这样： class OneClass { 从上下文分析，在//1处，本应该是从已经解包过的PackageNameItems中，取它的第N项；但这里误传入了解包前的packageNameItems。 具体情况我记不太清了。似乎输入文本可能有几种情况；多数情况不需要进一步处理，直接用外部那个变量就行，此时两个变量内容一致，不会触发bug；但少数情况下，外部那个变量需要进一步处理，这才能提取到正确的内容。这种情况下，两个变量内容不同，误用了前一个变量就读不到正确数据了。 这是个极为隐蔽的逻辑错误。和变量作用域相关的故障都很隐蔽。别说之前不知道原因瞎找了，我拿着整个调用链的详细记录，也是看了很多遍才发觉这两个变量的名字似乎有些意思，这才沿着这条线追查下去…… 总之，意外的输出信息弄得测试者一脸懵逼，因为这时候根本就不应该有这种信息；也幸好他的检查条件设的比较窄，只有正常返回可通过，其他一概抛异常崩掉——于是这个异常就被我的debug工具抓到，自动记录了调用栈信息。 但这又是个极为简单的bug。只需把最后那次访问时，首字符小写的变量名改成大写，故障就不再复发。 就这么简单个首字符大小写搞错、误访问了外部变量的bug，在问题单上挂了好些年，前前后后换了很多人经手，但就是没人能抓到它。 最终，奇葩的bug还是需要犀利的工具。 事实上，在这个工具的帮助下，我们还一口气横扫了系统中遗留的所有陈年老bug；以至于有人开始担心“（问题全都解决了）将来我们这个组还有存在的意义吗？”  RECOMMEND - 点个在看你最好看 - |
|
|
