strace在项目开发中的一点实践

在测试中遇到问题或者不合乎期望的情况下，我们第一反应常常是问是不是我们的测试方法，工具，配置或者数据有问题。如果能借助log等手段看到产品运行时的内部，到是可以解答不少疑惑，但是如果不幸（其实是幸运）做的是一个新的产品，还不是完善，包括log，那么很多时候遇到问题测试人员会觉得很无助，在这个时候我们可能需要借助一些工具。

strace就是这样的一个工具，它让你在没有源码，没有log的情况下可以看到进程运行时的一些“内幕”，只要是系统调用和信号，也就是进程和OS之间打交道的一些过程，也包括数据。我这里说的限于Linux，其他平台也有类似的工具，其实strace最早也是源于SunOS （详细用法和历史看这里： http://linux.die.net/man/1/strace

下面用个小小的例子来说明一下使用的情况。
产品需要对网络包做一些处理，但是如果想明确的指导到底是哪个模块做了处理（这里是block），在目前的状况下还不是很容易，另外也不能排除是测试环境和系统的原因导致包丢失，所以最好的办法是找到明确的证据。

以下是client端抓包的结果。可以看到在client发出了GET请求之后，没有收到server端的response，然后重传了两次（工具的设置），再次被无视之后发RST自行了断了。

下面是server端抓包的结果。可以看到server是收到了client的请求，而且也正常回复了（编号12的包），然后server觉得没有别的东西要传了，发FIN关了连接，进入半close状态。接下来发现response没有发成功，然后重传了两次（#15， #16）, 发现client端还是没有响应，然后不得不RST了。

从以上情况可以比较明显的看出来server的response被中间的设备阻止了，然后这个TCP连接后面的包都不通了。

接下来的问题是谁block了这些包，中间是怎么处理的。
下面我们用strace进去看一下。
基本的命令是：strace -T -tt -e trace=network [lannch_command]

除了分析这个问题，发现strace可以提供很多的细节，也很有趣。输出太多，摘录其中部分。

下面是strace看到的client发起SYN的第一个包。

后面还有两行：

core_pkt_hook:504: packet #1 passed
core_pkt_allocator_put:126: destroying packet #1

所以可以发现这个包顺利通过，然后buf中的数据被删除。
其实在上面的截图中，你会发现其实strace的输出按协议的层次展开的，本来协议栈的处理过程也是这样。现实ETH层的结果，然后是IP的，TCP的，到payload。层次很清楚，而且数据也帮忙解析出来了，debug很方便。个人觉得，部分程度，甚至可以代替tcpdump和wireshark，如果只是观察一些很基本的东西，当然包多了或者要看更detail这个是不行的。

接下来是第二个包

嗯，server回的ACK+SYN，顺利通过。

好吧，我们直接来看看client一直期待但是没有收到的第五个包，也就是server的HTTP response。

嗯，看起来没什么特别的。但是因为触发了一些规则，导致这个包没有到达client。

从上面的输出可以很清楚的看到因为触发了一些rule，导致这个包被drop了，悄悄的，所以两边都不知道，然后各自重传了。

至此，这个简单的分析过程就完成了，这样我们就知道了这个丢包的原因是什么，是不是按我们期望的，产品真正的work了。而且前提是没有依赖于任何产品的log和源码。

这里监控的只是网络访问，其实strace可以监控各种各样的系统调用。以上只是冰山一角，其实它可以做更多的事情，值得继续使用和研究。而且还有人写strace analyzer
http://clusterbuffer.wetpaint.com/page/Strace+Analyzer+-+Previous+Edition


以下是使用过程中的一些小notes。
1. 遇到过以下error
attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted.
后来发现是因为前一个strace在后台忘了停掉，再起一次的时候就报这个错。

2. 结果输出
strace的信息量很大，全部打到屏幕太多了，可以用-o输出到问题，或者自己重定向，默认很多是当stderr （也是fd 2）输出，所以可以 2>&1

3. 有两种启动模式，直接启动被监控的进程，或者-p 来attach到一个正在运行的进程。
理论上两种模式对于监控应该没有太大的差别，但是在我的环境里面，-p模式一直不work，还不清楚为什么，可能和我们自己编译的kernel有关，或者被监控的daemon有什么特别，还需要研究。同时我试过了4.5.17和4.6两个版本都是如此，比较费解。