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: , 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: , 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间隔过快也会出现此问题。
1、客户端主动关闭连接,是因为过了设置的超时时长就会关闭连接。这个又回到了10s的超时时长和频繁的发生time out现象的问题上了。
2、提交POST请求过快,nginx会认为属于不安全的请求,便主动拒绝连接。这个有可能是客户端那边不间断的测试数据导致,对于这种情况,可以对nginx的配置文件进行配置以下参数来进行不主动关闭。
proxy_ignore_client_abort on;
但是这样配置是不安全的。此时为了解决问题,就怀着激动的心先配置测试下。
可悲的是配置了该参数,发现还是不能解决问题。心里落差再一次发生。不过没有关系,终究还是通过日志能发现各种问题的。
在确定排除了第二点的疑问后,回到第一点(也就是3.1的问题上),为什么客户端那边测试的https的协议,在http协议里同样会出现该问题。这里的疑点重重呀。于是着重从这里下手。
客户端测试的接口文件是放在某个应用的目录下,虽然不能直接访问接口文件,但是可以访问其应用web目录。
通过访问web目录和结合日志发现了问题的所在:
1、nginx proxy使用的是默认的轮询,所以每一次可能会调度到不同的后端服务器上。而此刻访问刷新页面时,其中一次会有些卡顿,看后台日志发现每次卡顿时都会出现一个报错。
2、出现报错的同时,正常的日志也会出现一次成功的请求。在看页面又出现了一次刷新。这就解释了之前同一个时间点出现两次请求的现象了。
3、此时在回头去看报错日志就很容易的看出问题所在了,发现所有的error都属于upstream中的同一台tomcat。就说明是这台tomcat有问题。
在nginx中down掉这台tomcat,客户端那边测试一切OK。问题到此解决。至于为什么这台有问题,是白天开发直接动过tomcat的代码。问题只能白天上班来配合查找代码的问题。
四、总结
经过此次的排错,总结一下:
1、遇到问题要冷静处理,从最基础的开始排查。
2、善于利用各应用程序的日志进行错误跟踪。
3、还是要对各应用做到了然于心,对于各类报错尽量知道大概是什么问题。从哪里排查。
搞完问题,记录下来发现时间已经不早了,是该休息休息,为明天有更好的战斗状态!
更多Nginx相关教程见以下内容:
搭建基于Linux6.3+Nginx1.2+PHP5+MySQL5.5的Web服务器全过程
CentOS 6.3下配置Nginx加载ngx_pagespeed模块