记一次线上超时问题的发现、排查、定位以及解决过程

最近从性能、监控方面对引擎进行优化，这不，监控刚上了，就发现了一个很严重的问题--超时。

今天，借助此文，分享下该问题的发现、排查以及解决过程！

业务背景

在广告业务中，分为效果广告、KA广告以及三方广告等。效果广告和KA广告一般都仅限于内网，也就是说在内网中通过RPC进行访问，而三方广告，则需要访问外网，因为外网环境以及每家三方广告主的处理能力不同，导致性能不同。本次的超时就是针对的某个三方广告主。

本次针对三方的业务监控中，包括对三方广告主的请求数、返回数、qps、rt等指标。

收到报警

增加了监控的业务上线后，根据引擎监控系统来查看三方的基础数据监控，如下：

通过上述图表，看了下平均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

网络很稳定，看来跟网络没关系，只能通知对方。

双方沟通

跟对方反馈其rt超时很严重后，对方第一反应是内部有些广告主太耗时，于是其关闭了超时严重的广告主，然后让我这边继续观察。

待对方关闭耗时长的广告主后，重新打开监控报警(之前因为报警太频繁，暂时关闭了报警)，然后没有几分钟，报警又又又来了。

赶紧在群里跟对方反馈，对方也是一脸懵逼，双方开始一起排查问题，毕竟没人跟钱过不去😁

为了便于尽快发现，在测试环境尝试将超时时间设置为2s，然后模拟发送请求，果不其然，超时。。。

看了对方的反馈，对方在服务内部也设置了超时，如果200ms内没有得到有效广告，则返回，也就是说对方也做了200ms的超时控制，很奇怪。。。

在测试环境将超时时间设置为50s，仍然有超时现象。。。

对接群沟通多少有点影响到别人，于是勾搭了对方的技术，开始私聊（此处开始甩锅模式）

不过，甩锅归甩锅，问题还得解决。开始尝试使用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;

线上使用的版本果然没有处理此种情况，再跟线上做对比，改动如下：

好了，问题已经解决，原因也已经找到，毕竟不是大bug，为了稳妥起见，还是不升级了，以稳定为主，谁知道升级后又会出现什么意想不到的问题呢😁

结语

该问题从发现到解决，大概用了2天的时间。其实，从文章的目录结构就能发现，整个问题发现以及解决过程跟文章目录结构一致:收到报警->双方沟通->业务代码->线上抓包->同类对比->问题解决->原因分析->深入源码。