Nginx Proxy timeout排错

1、环境

  当前的环境为nginx做为前端反向代理，upstream为两台tomcat。

2、缘由

  因为最近项目属于初期阶段，平日加班也比较多，恰好碰到一天没有什么问题的时间，我早早的收拾装备开心的坐上了地铁奔向家里。

  此时，听着音乐的我快乐的坐在地铁上，忽然音乐戛然而止，响起了来电的铃音。一种很差的预感油然而生，看来是有问题了。因而乎我拿出电话看到了咱们老大的名字闪如今手机屏幕上，深呼一口气，接起电话。就听见咱们老大说如今客户端那边报错等什么什么的。因为地铁里杂音很大，信号又不是太好，就没细问。反正就是服务器端有问题，我就先应答下来。此时的我尚未到家，因而就说到家了再看。因而老大就挂了电话。我就在内心回想到底说的是什么问题，惋惜回忆了半天终仍是没有听清说了什么。

3、排错

  到家打开电脑，登上QQ，就看到了群里client那边再反映的问题，截图显示部分请求服务端的资源出现了request timed out的现象。因而我就登录到服务器端。首先查看各个进程是否正常。在肯定正常以后，访问页面测试下也是正常的。因为客户端调用的是接口文件，浏览器没有办法直接测试访问，只能经过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的proxy的一些超时时间的问题，因而就修改了time out的时间设置。

  再次测试仍是有此问题，我仔细想了一下，忽然发现这边测试的是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"

  能够看到日志里面的错误码和报错信息发生了改变。按照这个提示，应该是upstream向nginx发送了重置的请求，这是为何呢？

  网上搜索了一下，发现大部分说的都仍是time out的问题，有个别说是客户端get的头过大，可是明显这里用的是POST方法。那仍是按照time out去查找问题看看，因而又想客户端那边咨询下是否设置了超时时长，客户端那边给的是设置了10s的超时时长。这样看来应该也不会有问题呀。10s的状况下应该是足够服务器处理和响应了。

  此时尚未想到问题在什么地方，只能多监控写日志看看，因而把http的访问日志和错误日志以及https的访问日志和错误日志都以tail的方式实时的监控着。就在这些日志监控当中，忽然发现了几点奇怪的现象:

  3.一、http的错误日志也有connection time out的现象

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.二、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, client has closed connection */.就是说客户端主动关闭了链接，或者nginx两次提交post间隔过快也会出现此问题。

  一、客户端主动关闭链接，是由于过了设置的超时时长就会关闭链接。这个又回到了10s的超时时长和频繁的发生time out现象的问题上了。

  二、提交POST请求过快，nginx会认为属于不安全的请求，便主动拒绝链接。这个有多是客户端那边不间断的测试数据致使，对于这种状况，能够对nginx的配置文件进行配置如下参数来进行不主动关闭。

proxy_ignore_client_abort on;

  可是这样配置是不安全的。此时为了解决问题，就怀着激动的心先配置测试下。

  可悲的是配置了该参数，发现仍是不能解决问题。内心落差再一次发生。不过没有关系，终究仍是经过日志能发现各类问题的。

  在肯定排除了第二点的疑问后，回到第一点(也就是3.1的问题上)，为何客户端那边测试的https的协议，在http协议里一样会出现该问题。这里的疑点重重呀。因而着重从这里下手。

  客户端测试的接口文件是放在某个应用的目录下，虽然不能直接访问接口文件，可是能够访问其应用web目录。

  经过访问web目录和结合日志发现了问题的所在：

  一、nginx proxy使用的是默认的轮询，因此每一次可能会调度到不一样的后端服务器上。而此刻访问刷新页面时，其中一次会有些卡顿，看后台日志发现每次卡顿时都会出现一个报错。

  二、出现报错的同时，正常的日志也会出现一次成功的请求。在看页面又出现了一次刷新。这就解释了以前同一个时间点出现两次请求的现象了。

  三、此时在回头去看报错日志就很容易的看出问题所在了，发现全部的error都属于upstream中的同一台tomcat。就说明是这台tomcat有问题。

  在nginx中down掉这台tomcat，客户端那边测试一切OK。问题到此解决。至于为何这台有问题，是白天开发直接动过tomcat的代码。问题只能白天上班来配合查找代码的问题。

4、总结

  通过这次的排错，总结一下:

  一、遇到问题要冷静处理，从最基础的开始排查。

  二、善于利用各应用程序的日志进行错误跟踪。

  三、仍是要对各应用作到了然于心，对于各种报错尽可能知道大概是什么问题。从哪里排查。

  

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