排错是什么意思

NginxProxytimeout排错

一.环境

现在的环境是nginx作为前端反向代理，上游是两个tomcat。

第二，原因

最近项目处于起步阶段，工作日加班时间很多。刚好一天没问题，我早早收拾好装备，高高兴兴地坐地铁赶回家。

此时，我正开心地坐在地铁上，一边听着音乐。突然，音乐戛然而止，来电铃声响起。一种不好的感觉油然而生，似乎哪里不对劲。于是我拿出手机，看到手机屏幕上闪烁着我们老板的名字。我深吸一口气，拿起电话。我听我们老板说客户报错之类的。因为地铁里噪音很大，信号也不是很好，所以没详细问。反正服务器端有问题，我先回答。还没到家，回家再看。于是老板挂了电话。我脑子里记住了问题是什么，但过了很久还是听不清我说了什么。

第三，故障排除

当我打开家里的电脑，登上QQ，在群里看到了客户端反映的问题。截图显示请求服务器的一些资源请求超时。所以我登录了服务器。首先检查各流程是否正常。确定正常后，测试下访问页面也正常。由于客户端调用接口文件，浏览器没有办法直接测试访问，只能通过nginx的日志来检查问题。

客户端正在测试https的协议，所以此时检查https的一些日志:

2015/08/06 19:15:29 [error] 17709#0: *1380648 upstream timed out (110: Connection timed out) while sending request to upstream, client: xxx, server: www.xxxx.com, request: "POST /xxx/pub/xxx.do HTTP/1.1", upstream: "http://xxxx:8082/xxx.do", host: "www.xxxx.com:443" 2015/08/06 19:16:11 [error] 17709#0: *1380648 upstream timed out (110: Connection timed out) while sending request to upstream, client: xxx, server: www.xxxx.com, request: "POST /xxx/pub/xxx.do HTTP/1.1", upstream: "http://xxxx:8082/xxx.do", host: "www.xxxx.com:443"  2015/08/06 19:17:29 [error] 17709#0: *1380648 upstream timed out (110: Connection timed out) while sending request to upstream, client: xxx, server: www.xxxx.com, request: "POST /xxx/pub/xxx.do HTTP/1.1", upstream: "http://xxxx:8082/xxx.do", host: "www.xxxx.com:443" 2015/08/06 19:29:29 [error] 17709#0: *1380648 upstream timed out (110: Connection timed out) while sending request to upstream, client: xxx, server: www.xxxx.com, request: "POST /xxx/pub/xxx.do HTTP/1.1", upstream: "http://xxxx:8082/xxx.do", host: "www.xxxx.com:443"

日志的格式与上面的类似。看到这些，我想到了一些可能是nginx代理的超时问题，于是修改了超时的时间设置。

再次测试时还是有这个问题。我仔细想了想，突然发现这里的测试是https，而我修改的好像只是http的超时，于是又修改了一遍，暗暗兴奋是时候OK了。没想到修改后，客户端测试还是一样的问题。此时有些郁闷。

当我实时监控后台日志时，我再次发现尽管报告了错误，但还是有一些不同之处:

2015/08/06 19:47:31 [error] 17708#0: *1381368 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxx.com, request: "POST /xxx/xxx/xxxx.do HTTP/1.1", upstream: "http://xxx.xxx.xxx:8082/xxx/home/xxx.do", host: " 2015/08/06 19:50:11 [error] 12300#0: *1381368 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxx.com, request: "POST /xxx/xxx/xxxx.do HTTP/1.1", upstream: "http://xxx.xxx.xxx:8082/xxx/home/xxx.do", host: "www.xxx.com:443"  2015/08/06 19:55:04 [error] 132648#0: *1381368 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxx.com, request: "POST /xxx/xxx/xxxx.do HTTP/1.1", upstream: "http://xxx.xxx.xxx:8082/xxx/home/xxx.do", host: "www.xxx.com:443"

您可以看到日志中的错误代码和错误信息已经更改。根据这个提示，应该是上游向nginx发送了复位请求。为什么？

网上搜了一下，发现大部分还是关于超时的问题。其中有人说clientget的头太大了，但显然这里用的是POST方法。然后根据超时查找问题，然后询问客户端是否设置了超时期限。客户端给出10s的超时时间。这样看来应该没什么问题。10秒应该足够服务器处理和响应了。

这个时候我还没有想到问题出在哪里，只能监控写日志，所以我用tail的方式实时监控http访问日志和错误日志以及https访问日志。在这些日志监控中，突然发现了几个奇怪的现象:

3.1.http的错误日志也有连接超时的现象。

2015/08/06 19:29:44 [error] 17708#0: *1380926 upstream timed out (110: Connection timed out) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxxx.com, request: "GET /xxx/xxx/xxx.png HTTP/1.1", upstream: "http://xxx.xxx.xxx:8082/xxx/p_w_picpath/xxx.png", host: "www.xxx.com", referrer: "http://www.xxx.com/xxx/xxx/xxx.do?user_id=57&from=singlemessage&isappinstalled=1" 2015/08/06 19:29:44 [error] 17708#0: *1380930 upstream timed out (110: Connection timed out) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxx.com, request: "GET /xxx/xxx/xxx.png HTTP/1.1", upstream: "http://xx.xxx.xxx.xxx:8082/xxx/xxx/xxx.png", host: "www.xxx.com", referrer: "http://www.xxx.com/xxx/xxx/xxx.do?user_id=57&from=singlemessage&isappinstalled=1"

3.2.两个请求将同时出现在https访问日志和错误日志中。

# 错误日志 2015/08/06 21:58:59 [error] 22498#0: *527 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: www.xxx.com, request: "POST /xxx/xxx/xxx.do HTTP/1.1", upstream: "http://xxx.xxx.xxx.xxx:8082/xxx/xxx/xxx.do", host: "www.xxx.com:443" # 访问日志 xxx.xxx.xxx.xxx - - [06/Aug/2015:21:58:59 +0800] "POST /xxx/xxx/xxx.do HTTP/1.1" 200 1100 "-" "xxx/1.1.0 (iPhone Simulator; iOS 8.1; Scale/2.00)" "-"

从上面可以看出，同一时间点有两个请求，一个成功，一个失败，访问日志中有很多499响应码的请求。499响应代码表示/*499，客户端已关闭连接*/。也就是说客户端主动关闭了连接，或者nginx的post提交间隔太快。

1.客户端主动关闭连接，因为它将在设置的超时期限后关闭连接。这又回到了10s超时，频繁超时的问题。

2.如果POST请求提交太快，nginx会认为是不安全的请求，所以会主动拒绝连接。这可能是客户端的测试数据没有中断造成的。在这种情况下，nginx的配置文件可以配置以下参数来主动关机。

proxy_ignore_client_abort on;

但是这种配置并不安全。这时候为了解决问题，先兴奋地配置测试。

可悲的是，配置了这个参数，还是解决不了问题。心里的落差又发生了。不过没关系。毕竟各种问题都可以通过日志发现。

在确认第二个问题已经排除之后，我们再回到第一点(也就是3.1的问题)。为什么客户端测试的https协议在http协议中也有同样的问题？这里有很多疑点。所以我从这里开始。

客户端的接口文件放在应用程序的目录中。虽然不能直接访问接口文件，但是可以访问它的应用程序web目录。

通过访问web目录，结合日志，我们发现了问题:

1.nginx代理使用默认轮询，因此每次都可能被调度到不同的后端服务器。此刻，访问刷新页面时，其中一个会被卡住。看后台日志，发现每次卡突然出现错误。

2.在出现错误的同时，正常日志中会出现一个成功的请求。再看页面，又有刷新。这就解释了之前两个请求同时出现的现象。

3.这时候回头看看错误日志就很容易看出问题了，发现所有错误都属于upstream中的同一个tomcat。说明这只雄猫有问题。

在nginx中关闭这个tomcat，并在客户端测试一切正常。问题在这里解决了。至于这个为什么会有问题，就是开发白天直接接触tomcat的代码。问题只能白天工作来配合找码的问题。

四。摘要

完成故障排除后，总结:

1.遇到问题要冷静处理，从最基础的开始。

2.善于利用各种应用程序的日志来跟踪错误。

3.还是要搞清楚每一个应用，对于各种错误尽量知道是什么问题。去哪里查。

做完题，记录下来，发现时间不早了。该休息了，为了明天有更好的战斗状态！