在这春风明媚的日子里,有位T同学很苦恼。忙碌了一整天,有个BUG愣是定位不出来。简单描述呢,现象是这样子的:
第一次处理是正常的,但是后续的处理就是报错。sendto()调用错误码是 EISCONN(已被连接)。
忧伤的问题
当然,代码BUG的范围也很快确定了,就是新加入的statsd-client-cpp工具库里。代码量不到两百行,失败的地方就是在sendto()的执行里(代码看这儿)。一看错误码(EISCONN,比较少见),说“socket已经被连接”——但咱这明明是UDP协议啊,无连接无connect的!
T同学咨询了周围的大师们,翻阅了《Unix网络编程》(没错,这书在上次的故事里也出场了!),里面说:
sendto()函数的执行流大约是这样子的:
- 连接套接字;
- 输出数据报文;
- 断开套接字连接;
无语了。按照圣经里说法,连接都是被断开了的啊!还怎么会报错“已被连接”?!!
失败的补救
T同学比较耿直,对付BUG比较直接粗暴:报啥错误就解决啥错误!思路有俩:
-
人肉断开它!
这个实际上是行不通的(只能整个儿socket关闭销毁掉,不能只断开) -
连接了也继续发!
虽然一般情况下UDP协议的程序都是不管连接直接发sendto()的,但是先连接后再write()也是可行的。
于是按照方法2搞起!然而,实践证明这是不给力的,UDP对端根本没有收到任何数据!
正确的思路
这种头痛医头、瞎试几次的做法,本质上就不能算正确的方法。我们的思路应该是:
- 收集现象
- 分析原因
- 验证方案
- 解决问题
上面折腾了这么久,基本上还是只有一个错误码和代码出错的位置,现象数据太少了。T同学冷静下来后,开始祭出大杀器strace
工具程序!
strace程序能够捕抓系统调用(system call),并把这些调用接口的时间、参数、返回值、耗时等等都记录下来;输出信息可读性相当的高(比起gdb爽多了),能反映出系统最底层的运行状况,是后台开发程序员的居家旅行必备的强(zhuang)大(bi)工具。
神奇的零
具体strace的过程就不多说了。调整进程数量、执行strace、查看log、研究执行状况:
strace32 -s 10086 -o /tmp/Strace.log -tt -p $(pidof -s get_api_key)
终于发现一个关键现象:每次的连接socket()返回值都是0!
这里稍微解释一下,为什么零值会是很特殊:socket()返回值表示的是文件描述符;在POSIX标准里,有三个特殊的文件描述符值0、1、2,分别是STDIN(标准输入)、STDOUT(标准输出)、STDERR(标准错误)。所以默认情况下,零值都会作为STDIN(标准输入)
使用;只有当程序主动关闭了STDIN时,系统才会分配0值给socket()使用。
所以这时候思路有两个了:
- 假如系统分配的0值是正确的,那么得寻找0值后来被“弄坏”(已连接)的出现地方;
- 假如系统分配的0值是错误的,那么一定是某处BUG“失误”把STDIN释放掉了;
这种“辩证”的思路,让我忽然想起了《撸撸姐的超本格事件簿》里的给出各种伪解答搞笑助手:每次破案分析都至少有正反两个思路,看起来毫无盲点,但总是被撸撸姐指出第三种情况!哈哈哈!!!不过在现实场景里,正反两面都深入思考的做法,一般帮助很大的。
谁弄坏了0
所以0是被谁弄坏的?怎么弄坏的?
为了深入探究这个问题,得先了解一下程序运行的环境。这个工具库之前已经在现网的服务器里跑了很久,也有两个简约的单元测试。都没有发现过问题。这次是在往CGI接口里使用,运行环境是QZHTTP+FastCGI。
所以正常情况下,STDIN应该是CGI与qzhttp收包程序之间的连接,用来传递HTTP请求报文。而分析到的一个现象是,CGI程序的功能完全正常!也就是说程序之间传递数据(STDIN)是正常的……等等,STDIN(0值)不是分配给我们用吗??为毛还不影响功能啊啊啊???
秘诀就是——dup2(a, b)
!!这个函数能够把一个文件描述符的信息拷贝到另一个描述符里!所以文章最初出现的“EISCONN”错误的原因是:
原本UDP无连接的socket,被人用dup2()“篡改”了,于是就变成了另外的文件描述符,出现了“已连接”的状态。
写个小程序验证了一下,果然能够随便拷贝到STDIN描述符里!!!而再次strace抓包查看,也发现了明显的dup调用:
可以清晰看到对STDIN、STDOUT都做了dup2()操作!!!太邪恶了!!!火速在万能的StackOverflow.com上也找到了一篇关于0值的问答,里面有人提到了如何解决这个问题!那就是把0、1、2预留下来给系统!老子不陪你们玩零了!!(傲娇地离去!)
另一个思路
等等,刚才怎么这么快就进入了“解决问题”的节奏??? T同学的案例虽然因为屏幕不够长被滚动掉了,但是我们要分析所有的现象找到原因啊!
于是进入刚才的第二个思路:是谁把STDIN给关闭了??
深入strace的log,发现close(0)
首次出现的位置没有太特别,距离后来socket()和sendto()调用很遥远,暂时发现不了什么(后来细想,考虑时序其实是个误导)。
不过,因为是新引入的库导致了这个问题,基本上猜测要么就是库代码有BUG,要么是库和QZHTTP不兼容。重新阅读代码中与close()有关的片段,尝试梳理一下思路.果然发现一个问题:
d->sock
是个关键的值,而且没有初始化!一般来说变量没有初始化,会是一个随机的值;但是我们的场景里,StatsdClient
对象是一个单体实例,以static限定符实现的——所以是有初始值0的——刚好触发了BUG。
解决
再次核对代码逻辑和strace的log,脑补了一下执行的流程,基本上就确认BUG的原因就是这里了。
所以啊,在构造函数里增加一个初始化 d->sock = -1;
问题解决了。
写到这里的时候,忽然想起上两周给赵总用这个工具库,他也出现了一些诡异问题。当时他的现象是:随机出现accept错误。现在看来BUG原因都是一个,只不过赵总的使用方式是临时变量,没初始化的值就是随机值,因此偶然触发故障(他当时引起的是accept失败,也是描述符问题)。而这次是必现的问题,定位起来轻松一些。
思考
所以,要保持良好的代码编写习惯。顺手初始化了,就不会有这么纠结的问题了。