精简和总结上一篇文章：记一次线上超时问题的发现、排查、定位以及解决过程
原文：
https://www.cdsy.xyz/computer/servers/ns/230803/cd45189.html
引言
下面内容对于这篇文章做一个精简和总结。
归纳
问题
广告业务三方对接，个别广告主出现“超时”告警。
排查手段
- ping检查网络连接。
- curl分析各阶段业务耗时。
- 检查业务代码，增加日志断点调试。
- tcpdump抓包+wireshark分析
- 抓包对比其他对接方正常请求。
- 删除几个返回字段，问题解决。
- libcurl的源码分析，发现204的处理存在BUG。
- 修改服务器的libcurl的源码，问题解决。
结论
libcurl源码存在缺陷。
业务背景
本文介绍了一次超时问题，问题点是广告业务中第三方接口调用性能问题产生的超时问题排查。
针对三方的业务监控中，包括对三方广告主的请求数、返回数、qps、rt等指标
收到报警
鉴于业务的重要性，配置了邮件告警和短信告警两种，配置完成后，一键生效。配置之后没多久就收到告警。发现超时之后第一时间先ping下，看看网络间耗时，结果如下：
64 bytes from 114.67.237.131: icmp_seq=1 ttl=49 time=7.13 ms
64 bytes from 114.67.237.131: icmp_seq=2 ttl=49 time=6.37 ms
64 bytes from 114.67.237.131: icmp_seq=3 ttl=49 time=6.10 ms
64 bytes from 114.67.237.131: icmp_seq=4 ttl=49 time=6.07 ms
64 bytes from 114.67.237.131: icmp_seq=5 ttl=49 time=6.04 ms
64 bytes from 114.67.237.131: icmp_seq=6 ttl=49 time=6.07 ms
64 bytes from 114.67.237.131: icmp_seq=7 ttl=49 time=6.03 ms
64 bytes from 114.67.237.131: icmp_seq=8 ttl=49 time=6.09 ms
64 bytes from 114.67.237.131: icmp_seq=9 ttl=49 time=6.11 ms
64 bytes from 114.67.237.131: icmp_seq=10 ttl=49 time=6.03 ms
64 bytes from 114.67.237.131: icmp_seq=11 ttl=49 time=6.07 ms
网络很稳定，排除网络问题。
双方沟通，对接方第一时间关闭超时严重广告主，但是发现还是有超时的情况，并且后续沟通了解到对方在服务内部也设置了超时，如果200ms内没有得到有效广告，则返回。
继续分析
尝试使用curl来分析各个阶段的耗时：
curl -o /dev/null -s -w %{time_namelookup}::%{time_connect}::%{time_starttransfer}::%{time_total}::%{speed_download}"\n" --data-binary @req.dat https://www.baidu.com
输出结果如下
从上述结构可以看出，在time_starttransfe阶段，也就是说对方业务处理结果仍然会出现2s耗时，问题复现。
业务代码+日志测试排查
稳定运行5年的代码继续排查，通过log日志加测试case发送请求，可惜，日志并没有发现问题，也就是说业务是正常的。
线上抓包
通过tcpdump抓包来分析，wireshark解析后结果如下：
从上面抓包结果来看，在序号为6的位置，对方返回了http 204，然后又重新手动发了一次curl请求，在序号10的时候，对方又返回了http 204。
从发送请求到收到对方响应耗时38ms
此外，后面50s后client端（发送方）发送FIN请求关闭连接，从代码逻辑来分析，是因为超时导致的关闭连接。
所以结论就是抓包也没看出端倪。
同类对比
与其它家正常返回的做对比。具体做法是通过修改业务代码，输出http相关信息，输出内容如下：
curl_easy_setopt(handle_, CURLOPT_VERBOSE, 1L);
编译，运行，发起curl请求。
正常三方返回如下：
而超时的该家返回如下：
对比超时和正常的报文，超时的较正常的那一家，多了Content-Length、Content-Type等字段。
问题解决
联系对接放，将这几个字段去掉，我这边重新发起curl请求测试。
结果：发起curl请求，一切正常，在超时范围内返回。wrk压测，平均rt符合预期，看来问题就在这。
跟对方沟通后，对方修改代码，然后着手上线，上线后结果如下：
效果很明显，看来就是这个原因导致，超时问题解决了，收入也就蹭蹭地往上涨了😃。
分析原因
既然问题已经解决了，多少得知道原因吧，于是在搜索引擎上输入http 204 Content-Length hang，找到了有用信息，如下：
看来wget之前也存在此类问题，于是继续搜索标准，输出如下：
The presence of a message body in a response depends on both the request method to which it is responding and the response status code (Section 3.1.2). Responses to the HEAD request method (Section 4.3.2 of [RFC7231]) never include a message body because the associated response header fields (e.g., Transfer-Encoding, Content-Length, etc.), if present, indicate only what their values would have been if the request method had been GET (Section 4.3.1 of [RFC7231]). 2xx (Successful) responses to a CONNECT request method (Section 4.3.6 of [RFC7231]) switch to tunnel mode instead of having a message body. All 1xx (Informational), 204 (No Content), and 304 (Not Modified) responses do not include a message body. All other responses do include a message body, although the body might be of zero length.
深入源码
从上节标准可以看出，在http 204、304的时候，不允许返回Content-Length，那么如果返回了，libcurl又是如何处理的呢？
于是在curl的issue上进行了关键字搜索，得到了如下结果：
看来已经有人提过这个问题了，于是看了下当前线上libcurl的源码：
switch(k->httpcode) {
case 204:
/* (quote from RFC2616, section 10.2.5): The server has
* fulfilled the request but does not need to return an
* entity-body ... The 204 response MUST NOT include a
* message-body, and thus is always terminated by the first
* empty line after the header fields. */
/* FALLTHROUGH */
case 304:
/* (quote from RFC2616, section 10.3.5): The 304 response
* MUST NOT contain a message-body, and thus is always
* terminated by the first empty line after the header
* fields. */
if(data->set.timecondition)
data->info.timecond = TRUE;
k->size=0;
k->maxdownload=0;
k->ignorecl = TRUE; /* ignore Content-Length headers */
break;
线上使用的版本果然没有处理此种情况，再跟线上做对比，改动如下：
最后的解决办法是改动源码而不是进行升级。
结语
整个问题发现以及解决过程跟文章目录结构一致:收到报警->双方沟通->业务代码->线上抓包->同类对比->问题解决->原因分析->深入源码。
湘公网安备 43102202000103号