路由器连接isp服务器超时,联通路由器连接isp服务器超时

首页 > 实用技巧 > 作者：YD1662024-01-18 05:46:44

由上面的截图看到，本次出问题的请求总耗时42.74秒。

可以预见，通过捕获的日志完全可以看到Stalled那么久都发生了些什么鬼。

话不多说，切换到事件捕获页面，定位到出问题的请求，查看其详情。同时将该日志导出，永久保存！作为纪念，也方便以后再次导入查看。有兴趣的同学可以访问下方下载后进行导入，就可以清晰地查看到现场了，就好像你亲历了整个犯罪现场一样。

日志还原

此刻右边出现的便是该问题请求的详细日志。

日志解读

下面不妨把日志文件贴出来先：

193486: URL_REQUEST http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593 Start Time: 2015-01-02 17:51:05.323 t= 1 [st= 0] REQUEST_ALIVE [dt=42741] t= 1 [st= 0] URL_REQUEST_DELEGATE [dt=0] t= 1 [st= 0] URL_REQUEST_START_JOB [dt=42740] --> load_flags = 339804160 (BYPASS_DATA_REDUCTION_PROXY | MAYBE_USER_GESTURE | REPORT_RAW_HEADERS | VERIFY_EV_CERT) --> method = "GET" --> priority = "LOW" --> url = "http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593" t= 2 [st= 1] URL_REQUEST_DELEGATE [dt=0] t= 2 [st= 1] HTTP_CACHE_GET_BACKEND [dt=0] t= 2 [st= 1] HTTP_CACHE_OPEN_ENTRY [dt=0] t= 2 [st= 1] HTTP_CACHE_ADD_TO_ENTRY [dt=0] t= 2 [st= 1] HTTP_CACHE_READ_INFO [dt=0] t= 2 [st= 1] URL_REQUEST_DELEGATE [dt=0] t= 2 [st= 1] HTTP_STREAM_REQUEST [dt=2] t= 4 [st= 3] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 193488 (HTTP_STREAM_JOB) t= 4 [st= 3] -HTTP_STREAM_REQUEST t= 4 [st= 3] HTTP_TRANSACTION_SEND_REQUEST [dt=0] t= 4 [st= 3] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1 Host: qa.tieba.baidu.com Connection: keep-alive Accept: application/json, text/plain, */* User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 Referer: http://qa.tieba.baidu.com/project/ Accept-Encoding: gzip, deflate, sdch Accept-Language: en-US,en;q=0.8 Cookie: [268 bytes were stripped] t= 4 [st= 3] -HTTP_TRANSACTION_SEND_REQUEST t= 4 [st= 3] HTTP_TRANSACTION_READ_HEADERS [dt=21301] t= 4 [st= 3] HTTP_STREAM_PARSER_READ_HEADERS [dt=21301] --> net_error = -101 (ERR_CONNECTION_RESET) t=21305 [st=21304] HTTP_TRANSACTION_RESTART_AFTER_ERROR --> net_error = -101 (ERR_CONNECTION_RESET) t=21305 [st=21304] -HTTP_TRANSACTION_READ_HEADERS t=21305 [st=21304] HTTP_STREAM_REQUEST [dt=3] t=21307 [st=21306] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 193494 (HTTP_STREAM_JOB) t=21308 [st=21307] -HTTP_STREAM_REQUEST t=21308 [st=21307] HTTP_TRANSACTION_SEND_REQUEST [dt=3] t=21308 [st=21307] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1 Host: qa.tieba.baidu.com Connection: keep-alive Accept: application/json, text/plain, */* User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 Referer: http://qa.tieba.baidu.com/project/ Accept-Encoding: gzip, deflate, sdch Accept-Language: en-US,en;q=0.8 Cookie: [268 bytes were stripped] t=21311 [st=21310] -HTTP_TRANSACTION_SEND_REQUEST t=21311 [st=21310] HTTP_TRANSACTION_READ_HEADERS [dt=21304] t=21311 [st=21310] HTTP_STREAM_PARSER_READ_HEADERS [dt=21304] --> net_error = -101 (ERR_CONNECTION_RESET) t=42615 [st=42614] HTTP_TRANSACTION_RESTART_AFTER_ERROR --> net_error = -101 (ERR_CONNECTION_RESET) t=42615 [st=42614] -HTTP_TRANSACTION_READ_HEADERS t=42615 [st=42614] HTTP_STREAM_REQUEST [dt=12] t=42627 [st=42626] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 193498 (HTTP_STREAM_JOB) t=42627 [st=42626] -HTTP_STREAM_REQUEST t=42627 [st=42626] HTTP_TRANSACTION_SEND_REQUEST [dt=2] t=42627 [st=42626] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1 Host: qa.tieba.baidu.com Connection: keep-alive Accept: application/json, text/plain, */* User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 Referer: http://qa.tieba.baidu.com/project/ Accept-Encoding: gzip, deflate, sdch Accept-Language: en-US,en;q=0.8 Cookie: [268 bytes were stripped] t=42629 [st=42628] -HTTP_TRANSACTION_SEND_REQUEST t=42629 [st=42628] HTTP_TRANSACTION_READ_HEADERS [dt=112] t=42629 [st=42628] HTTP_STREAM_PARSER_READ_HEADERS [dt=112] t=42741 [st=42740] HTTP_TRANSACTION_READ_RESPONSE_HEADERS --> HTTP/1.1 200 OK Date: Fri, 02 Jan 2015 09:51:48 GMT Content-Type: application/json; charset=UTF-8 Transfer-Encoding: chunked Connection: keep-alive Cache-Control: no-cache tracecode: 31079600320335034634010217 tracecode: 31079600320537995786010217 Server: Apache t=42741 [st=42740] -HTTP_TRANSACTION_READ_HEADERS t=42741 [st=42740] HTTP_CACHE_WRITE_INFO [dt=0] t=42741 [st=42740] HTTP_CACHE_WRITE_DATA [dt=0] t=42741 [st=42740] HTTP_CACHE_WRITE_INFO [dt=0] t=42741 [st=42740] URL_REQUEST_DELEGATE [dt=0] t=42741 [st=42740] -URL_REQUEST_START_JOB t=42741 [st=42740] URL_REQUEST_DELEGATE [dt=0] t=42741 [st=42740] HTTP_TRANSACTION_READ_BODY [dt=0] t=42741 [st=42740] HTTP_CACHE_WRITE_DATA [dt=0] t=42741 [st=42740] HTTP_TRANSACTION_READ_BODY [dt=0] t=42741 [st=42740] HTTP_CACHE_WRITE_DATA [dt=0] t=42742 [st=42741] -REQUEST_ALIVE

首先，日志显示的总耗时与上面网络面板截图的总耗时是吻合的，都是42.74秒，说明我们定位正确。

以下时间均以毫秒计

日志第一列为时间线，自请求发起时算。 第二列为每步操作所逝去的时间，时间差的概念，与第三列里面的dt不同，它会积累前面的耗时。 第三列为具体的事件，以及相应事件的耗时dt，此耗时为绝对耗时。

号对应事件开始，-号对应事件结束，也就是说他们必然成对出现。住里是展开后更加详细的子事件。直到不能再细分。

如果说一开始接触到这个日志时手足无措的话，我们来看一下正常情况下的日志是怎样的，有对比才有发现。

以下随便摘取一次正常请求的日志，如下：

384462: URL_REQUEST http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593 Start Time: 2015-01-03 20:23:54.698 t=1556 [st= 0] REQUEST_ALIVE [dt=172] t=1556 [st= 0] URL_REQUEST_DELEGATE [dt=0] t=1556 [st= 0] URL_REQUEST_START_JOB [dt=171] --> load_flags = 335609856 (BYPASS_DATA_REDUCTION_PROXY | MAYBE_USER_GESTURE | VERIFY_EV_CERT) --> method = "GET" --> priority = "LOW" --> url = "http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593" t=1557 [st= 1] URL_REQUEST_DELEGATE [dt=4] t=1557 [st= 1] DELEGATE_INFO [dt=4] --> delegate_info = "extension Tampermonkey" t=1561 [st= 5] -URL_REQUEST_DELEGATE t=1561 [st= 5] HTTP_CACHE_GET_BACKEND [dt=0] t=1561 [st= 5] HTTP_CACHE_OPEN_ENTRY [dt=1] --> net_error = -2 (ERR_FAILED) t=1562 [st= 6] HTTP_CACHE_CREATE_ENTRY [dt=0] t=1562 [st= 6] HTTP_CACHE_ADD_TO_ENTRY [dt=0] t=1562 [st= 6] URL_REQUEST_DELEGATE [dt=0] t=1562 [st= 6] HTTP_STREAM_REQUEST [dt=2] t=1564 [st= 8] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 384467 (HTTP_STREAM_JOB) t=1564 [st= 8] -HTTP_STREAM_REQUEST t=1564 [st= 8] HTTP_TRANSACTION_SEND_REQUEST [dt=1] t=1564 [st= 8] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1 Host: qa.tieba.baidu.com Connection: keep-alive Accept: application/json, text/plain, */* User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 Referer: http://qa.tieba.baidu.com/project/ Accept-Encoding: gzip, deflate, sdch Accept-Language: en-US,en;q=0.8 Cookie: [2642 bytes were stripped] t=1565 [st= 9] -HTTP_TRANSACTION_SEND_REQUEST t=1565 [st= 9] HTTP_TRANSACTION_READ_HEADERS [dt=161] t=1565 [st= 9] HTTP_STREAM_PARSER_READ_HEADERS [dt=160] t=1725 [st=169] HTTP_TRANSACTION_READ_RESPONSE_HEADERS --> HTTP/1.1 200 OK Date: Sat, 03 Jan 2015 12:23:54 GMT Content-Type: application/json; charset=UTF-8 Transfer-Encoding: chunked Connection: keep-alive Cache-Control: no-cache tracecode: 14346880480340800522010320 tracecode: 14346880480253893130010320 Server: Apache t=1726 [st=170] -HTTP_TRANSACTION_READ_HEADERS t=1726 [st=170] HTTP_CACHE_WRITE_INFO [dt=0] t=1726 [st=170] HTTP_CACHE_WRITE_DATA [dt=0] t=1726 [st=170] HTTP_CACHE_WRITE_INFO [dt=0] t=1726 [st=170] URL_REQUEST_DELEGATE [dt=1] t=1726 [st=170] DELEGATE_INFO [dt=1] --> delegate_info = "extension Tampermonkey" t=1727 [st=171] -URL_REQUEST_DELEGATE t=1727 [st=171] -URL_REQUEST_START_JOB t=1727 [st=171] URL_REQUEST_DELEGATE [dt=0] t=1727 [st=171] HTTP_TRANSACTION_READ_BODY [dt=0] t=1727 [st=171] HTTP_CACHE_WRITE_DATA [dt=1] t=1728 [st=172] HTTP_TRANSACTION_READ_BODY [dt=0] t=1728 [st=172] HTTP_CACHE_WRITE_DATA [dt=0] t=1728 [st=172] -REQUEST_ALIVE

针对上面正常的请求，我们主要关注两部分，如下面的截图：

路由器连接isp服务器超时,联通路由器连接isp服务器超时(9)

这是正常的情况下，没有什么问题。并且日志里可以清晰地看到发送的请求头是什么，然后解析出来的响应头是什么。这跟在网络面板看到的是一致的。

再回到出问题的请求日志上来，同样我们只关注这两部分。如下面的截图：

路由器连接isp服务器超时,联通路由器连接isp服务器超时(10)

与正常相比，最后一次发送请求和读取响应头无异常，时间就多在了前面还有再次发送和请求的过程，细看时间都花在了以下两个事件中：

该事件的名称已经自我解读，意思是解析读取的响应头。但问题是紧接着下面报错了，

--> net_error = -101 (ERR_CONNECTION_RESET)

读取响应头时发生了链接重置的错误，有理由认为本次链接是不成功的，没拿到正确的响应头，于是解析不成功。时间都花在了这里，足足21秒之久，两个21秒造就了上面看到的Stalled了42秒之久。

问题似乎已经很明朗了。链接被重置。

在第三次尝试的时候正常了，于是正确返回，我们才看到了被解析的响应头被展示在了下面。也就是说在出问题的时候要么响应头未拿到，要么响应头非法导致解析不成功。而原因就是链接被重置。

那么接下来的工作就是对ERR_CONNECTION_RESET这个错误的追查了。

官方关于 ERR_CONNECTION_RESET 错误的解释

未找到官方相应的资料，Chrome官网上唯一关于此错误的描述是在安装Chrome时出现Error 101。我估计文档的撰写人员没想到谁会这么蛋疼想要看这些生涩的东西，除了开发者。既然你都是开发者了，那为什么不去看Chromium的源码。

好吧，唯一的途径似乎只能从源码中寻找了。作为只精JS的前端人员，现在要从C，C 代码中找答案了。估计追完这个问题，我会尝试为Chromium贡献代码。

慢着，在这之前，还是搜到一些关于这个错误的信息的。但似乎都不怎么靠谱。

比如这里提到，是因为ISP网络问题，实在无太可能。还有这是神马居然一个硬件网站但提到了这个错误，并且怀疑是*软导致Chrome出问题，但*软已经在上文被我们排除了。

Chromium 源码

那么这个错误究竟是什么。能不能找到点靠谱的解释。当然能，让我们进入到Chromium的源码中去。

ERR_CONNECTION_RESET被唤起的地方

在Chromium的源码中搜索该常量名，确实出现很多结果。联系到我们查看日志发现问题的上下文，是在解析响应头报的。所以我们定位到http_stream_parser.cc文件，同时注意到有一个文件叫net_errors_win.cc，所以猜测他是定义所有错误常量用的，也顺便打开之。

经过观察src/net/base/net_errors_win.cc 其路径和代码得知其中多为系统级别的错误，似乎跟我们的问题不是很关联，忽略该文件。

路由器连接isp服务器超时,联通路由器连接isp服务器超时(11)

http_stream_parser.cc文件中，ERR_CONNECTION_RESET仅出现一次。这给我们定位带来了极大的便利。

[chromium]//src/net/base/net_errors_win.cc:

// Returns true if |error_code| is an error for which we give the server a // chance to send a body containing error information, if the error was received // while trying to upload a request body. bool ShouldTryReadingOnUploadError(int error_code) { return (error_code == ERR_CONNECTION_RESET); }

这里定义了一个ShouldTryReadingOnUploadError 的方法，注释耐人寻味，这个时候，这样的情景，能否正确解读注释成为了比读懂代码更重要（这是我在看JS代码时永远无法体味到的感觉），下面尽可能对它进行理解：

在尝试发送一个请求体的时候，让服务器尝试发送一个带错误的响应体，如果我们接收到了该错误则返回true

我承认被上面的复杂从句打败！

那么我们来看这个方法被调用的场景。

现在我们点击上面的ShouldTryReadingOnUploadError方法，代码下方出现调用了该方法的地方，一共有两处。

分别点击进行查看。

459行DoSendHeadersComplete方法里进行了调用:

int HttpStreamParser::DoSendHeadersComplete(int result) { if (result < 0) { // In the unlikely case that the headers and body were merged, all the // the headers were sent, but not all of the body way, and |result| is // an error that this should try reading after, stash the error for now and // act like the request was successfully sent. if (request_headers_->BytesConsumed() >= request_headers_length_ && ShouldTryReadingOnUploadError(result)) { upload_error_ = result; return OK; } return result; }

虽然不太可能，但也不排除头部和请求体合并的情况，当所有头部发送完毕，请求体不一定，此时result便是需要稍后处理的一种错误，这里暂且先返回OK。

516行另一个DoSendBodyComplete方法里进行了调用:

int HttpStreamParser::DoSendBodyComplete(int result) { if (result < 0) { // If |result| is an error that this should try reading after, stash the // error for now and act like the request was successfully sent. if (ShouldTryReadingOnUploadError(result)) { upload_error_ = result; return OK; } return result; }

跟上面类似，如果result出错，稍后处理，先返回正常

这也与我们在日志中看到的情况相符，在前面再次错误后，这次请求并没有终止结束，而是尝试到了第三次并且以成功结束的。

但不管怎样，从这两个方法，一个DoSendHeadersComplete， 另一个DoSendBodyComplete，身上能体现出请求确实已经发出去。

TCP RST

另外，在net_error_list.h这个文件的109行，可以准确找到我们在日志中得到的101号错误。它的定义如下：

// A connection was reset (corresponding to a TCP RST). NET_ERROR(CONNECTION_RESET, -101)

从括号中的进一步解释可以知道，它代表TCP连接重置。

TCP

那么问题来了，什么是TCP连接重置？什么会引发TCP连接重置。从这篇文章中有比较详细的解答。

想要完全解释，本文似乎是不可能的了。但根据上面的文章，这里可以简单转述一下。

什么是TCP连接

它是一种协议。当网络上一个节点想与另一个节点通信时，双方需要选建立连接。而这个连接过程需要大家都懂的一种约定，TCP就是事先定好的一种约定，于是我们采用它吧，于是其中一个节点按照这个约定发起一建立连接的请求，另一节点收到后，根据该约定，便能读懂这个请求里各字段的意思：哦，丫这是想约我呢。

三次握手

继续上面的例子。A想与B通信，并且使用TCP。

首先A发起一个报文，其中包含自己的地址，想要连接的目标地址，自己用来连接的端口及目标机器的端口,etc.

B收到邀约，并且愿意付约。此刻B需要回传一个报文，告诉A我愿意跟你连接。

A收到B的肯定应答，到此A与B经历了三次通信或者说是握手，双方都没有异议，连接建立。

而连接断开的过程也颇为类似。双方中的一方比如说A先发起一个断开连接的报文FIN，B收到并确认，然后回传一个可以断开的报文FIN给A。此刻A收到并确认。此刻双方都确认后，连接可以安全断开，但还会保持一个等待断开的状态，大概持续4分钟，用于之前连接通路上未传输完成的数据进行善后。

什么是重置

上面提到了4分钟的等待时间，而重置RESET便是立即断开连接的手段。

发生重置的情况

到此重置的作用已然明了。也就是说，重置甚至算不上一个错误，它是TCP连接中的一种正常情况。但什么时候会发生重置，如何引起的。

上文列出了三种情况。

SMB Reset

简单举例来说，服务器提供了两个端口445，139进行服务，客户端同时去请求与这两个端口连接，服务器返回了两个端口可以被连接，此刻客户端择优选择一个进行连接，而重置另一个。

Ack, Reset

报文重置发生主要有以下情况：

TCP Reset due to no response

由于没有响应而被重置。当发起连接的一方连续发送6次请求未得到回应，此刻默认他们之间已经通过三次握手建立了连接并且通信有问题，发起的一方将连接重置。

Application Reset

除了上面的情况，找不到TCP内部自己发送的重置，则归为了这一类。程序内将连接重置。此种情况包含了所有你想得到想不到将连接断开的情况。有可能是程序内部逻辑重置的，所以不能完全认为此时发生了错误。

值得注意的是，上面列出的情况服务器的不确定性导致连接重置的可能性要合理些。Chrome 主动发起URL请求不太可能自己又重置掉，并且没有理由重置掉后又去重连。

进一步解读日志文件

上面Chromium源码部分的求证多少带有猜测成分。不妥。

因为没找到关于Chrome net-internal 日志的官方文档什么的，自身去解读始终是有局限的。不如提个ISSUE让Chromium开发人员来搭一把手吧。遂向Chromium提交ISSUE，请戳此查看，虽然我不认为现在遇到的这个问题跟Chrome有关并且属于Chrome的Bug，目的仅仅是看他们能否帮忙给出合理的日志解读来定位问题。

三天后（有点热泪盈眶），有同学回复，将日志所体现的问题诊断得似乎很有道理，可信。

1) We have a bunch of connections to qa.tieba.baidu.com, all were used successfully, and are now idle. 2) They all silently die for some reason, without us ever being informed. My guess is your personal router times out the connection, but this could also be your ISP, the destination server, or ever a real network outage (A short one) that prevents us from getting the connection closed message. 3) There’s a new request to qa.tieba.baidu.com. We try to reuse a socket. After 21 seconds, we get the server’s RST message (“I don’t have a connection to you.”). Since it was a stale socket, we’re aware this sometimes happens, so we just retry…And get the next idle socket in the list, which, after 21 seconds, gives us the same reset message. We try again, for the same reason. This time we don’t have another stale socket to try, so we use a fresh one. The request succeeds.

The real problem here is something is taking 21 seconds to send us the RST messages, despite the fact that a roundtrip to the server you’re talking to only takes about 100 milliseconds.

总结出来，两个问题：

Chrome Dev Tool 中时间线各阶段代表的意义

另附注一下Chrome Dev Tool 中请求的时间线各阶段代表的意义。 以下内容扒自Chrome 开发者文档页，然后我将它本地化了一下下。

路由器连接isp服务器超时,联通路由器连接isp服务器超时(12)

上一页1234下一页

栏目热文

文档排行

本站推荐

Copyright © 2018 - 2021 www.yd166.com., All Rights Reserved.