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、總結

  通過這次的排錯，總結一下:

  一、遇到問題要冷靜處理，從最基礎的開始排查。

  二、善於利用各應用程序的日誌進行錯誤跟蹤。

  三、仍是要對各應用作到了然於心，對於各種報錯儘可能知道大概是什麼問題。從哪裏排查。

  

搞完問題，記錄下來發現時間已經不早了，是該休息休息，爲明天有更好的戰鬥狀態！