Nginx Proxy timeout排錯

一、環境

  目前的環境為nginx作為前端反向代理，upstream為兩台tomcat。

二、原因

  由于最近項目屬于初期階段，平日加班也比較多，剛好碰到一天沒有什麼問題的時間，我早早的收拾裝備開心的坐上了地鐵奔向家裡。

  此時，聽着音樂的我快樂的坐在地鐵上，突然音樂戛然而止，響起了來電的鈴音。一種不好的預感油然而生，看來是有問題了。于是乎我拿出電話看到了我們老大的名字閃現在手機螢幕上，深呼一口氣，接起電話。就聽見我們老大說現在用戶端那邊報錯等什麼什麼的。由于地鐵裡雜音很大，信号又不是太好，就沒細問。反正就是伺服器端有問題，我就先應答下來。此時的我還沒有到家，于是就說到家了再看。于是老大就挂了電話。我就在心裡回想到底說的是什麼問題，可惜回憶了半天終還是沒有聽清說了什麼。

三、排錯

  到家打開電腦，登上QQ，就看到了群裡client那邊再反映的問題，截圖顯示部分請求服務端的資源出現了request timed out的現象。于是我就登陸到伺服器端。首先檢視各個程序是否正常。在确定正常之後，通路頁面測試下也是正常的。由于用戶端調用的是接口檔案，浏覽器沒有辦法直接測試通路，隻能通過nginx的日志檢視問題。

  用戶端那邊測試的是https的協定，此時就檢視https的部分日志：

1

2

3

4

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>15</code><code>:</code><code>29</code> <code>[error] </code><code>17709</code><code>#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"</code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>16</code><code>:</code><code>11</code> <code>[error] </code><code>17709</code><code>#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"</code>

<code> </code><code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>17</code><code>:</code><code>29</code> <code>[error] </code><code>17709</code><code>#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"</code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>29</code><code>:</code><code>29</code> <code>[error] </code><code>17709</code><code>#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"</code>

  日志格式就類似上面的這些類容，看到這些，我就想到可能是nginx的proxy的一些逾時時間的問題，于是就修改了time out的時間設定。

  再次測試還是有此問題，我仔細想了一下，突然發現這邊測試的是https，而我修改的好像隻是http的逾時時間，于是再次修改，心裡暗自激動的認為這下該OK了吧。沒想到修改完之後，用戶端那邊測試還是一樣的問題。此時就有些郁悶了。

  由于我實時的再監控着背景日志，再次發現雖然報錯，但是有些差別:

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>47</code><code>:</code><code>31</code> <code>[error] </code><code>17708</code><code>#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: "</code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>50</code><code>:</code><code>11</code> <code>[error] </code><code>12300</code><code>#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" </code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>55</code><code>:</code><code>04</code> <code>[error] </code><code>132648</code><code>#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"</code>

  可以看到日志裡面的錯誤碼和報錯資訊發生了改變。按照這個提示，應該是upstream向nginx發送了重置的請求，這是為什麼呢？

  網上搜尋了一下，發現大部分說的都還是time out的問題，有個别說是用戶端get的頭過大，但是明顯這裡用的是POST方法。那還是按照time out去查找問題看看，于是又想用戶端那邊咨詢下是否設定了逾時時長，用戶端那邊給的是設定了10s的逾時時長。這樣看來應該也不會有問題呀。10s的情況下應該是足夠伺服器處理和響應了。

  此時還沒有想到問題在什麼地方，隻能多監控寫日志看看，于是把http的通路日志和錯誤日志以及https的通路日志和錯誤日志都以tail的方式實時的監控着。就在這些日志監控當中，突然發現了幾點奇怪的現象:

  3.1、http的錯誤日志也有connection time out的現象

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>29</code><code>:</code><code>44</code> <code>[error] </code><code>17708</code><code>#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/image/xxx.png", host: "www.xxx.com", referrer: "http://www.xxx.com/xxx/xxx/xxx.do?user_id=57&amp;from=singlemessage&amp;isappinstalled=1"</code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>19</code><code>:</code><code>29</code><code>:</code><code>44</code> <code>[error] </code><code>17708</code><code>#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&amp;from=singlemessage&amp;isappinstalled=1"</code>

  3.2、https通路日志和錯誤日志在同一時間點會出現兩個請求

<code># 錯誤日志</code>

<code>2015</code><code>/</code><code>08</code><code>/</code><code>06</code> <code>21</code><code>:</code><code>58</code><code>:</code><code>59</code> <code>[error] </code><code>22498</code><code>#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"</code>

<code># 通路日志</code>

<code>xxx.xxx.xxx.xxx </code><code>-</code> <code>-</code> <code>[</code><code>06</code><code>/</code><code>Aug</code><code>/</code><code>2015</code><code>:</code><code>21</code><code>:</code><code>58</code><code>:</code><code>59</code> <code>+</code><code>0800</code><code>] </code><code>"POST /xxx/xxx/xxx.do HTTP/1.1"</code> <code>200</code> <code>1100</code> <code>"-"</code> <code>"xxx/1.1.0 (iPhone Simulator; iOS 8.1; Scale/2.00)"</code> <code>"-"</code>

  上述可以看到在同一個時間點出現了兩個請求，并且一個成功，一個失敗，并且通路日志有很多499響應碼的請求。而499響應碼是說/* 499, client has closed connection */.就是說用戶端主動關閉了連接配接，或者nginx兩次送出post間隔過快也會出現此問題。

  1、用戶端主動關閉連接配接，是因為過了設定的逾時時長就會關閉連接配接。這個又回到了10s的逾時時長和頻繁的發生time out現象的問題上了。

  2、送出POST請求過快，nginx會認為屬于不安全的請求，便主動拒絕連接配接。這個有可能是用戶端那邊不間斷的測試資料導緻，對于這種情況，可以對nginx的配置檔案進行配置以下參數來進行不主動關閉。

<code>proxy_ignore_client_abort on;</code>

  但是這樣配置是不安全的。此時為了解決問題，就懷着激動的心先配置測試下。

  可悲的是配置了該參數，發現還是不能解決問題。心裡落差再一次發生。不過沒有關系，終究還是通過日志能發現各種問題的。

  在确定排除了第二點的疑問後，回到第一點(也就是3.1的問題上)，為什麼用戶端那邊測試的https的協定，在http協定裡同樣會出現該問題。這裡的疑點重重呀。于是着重從這裡下手。

  用戶端測試的接口檔案是放在某個應用的目錄下，雖然不能直接通路接口檔案，但是可以通路其應用web目錄。

  通過通路web目錄和結合日志發現了問題的所在：

  1、nginx proxy使用的是預設的輪詢，是以每一次可能會排程到不同的後端伺服器上。而此刻通路重新整理頁面時，其中一次會有些卡頓，看背景日志發現每次卡頓時都會出現一個報錯。

  2、出現報錯的同時，正常的日志也會出現一次成功的請求。在看頁面又出現了一次重新整理。這就解釋了之前同一個時間點出現兩次請求的現象了。

  3、此時在回頭去看報錯日志就很容易的看出問題所在了，發現所有的error都屬于upstream中的同一台tomcat。就說明是這台tomcat有問題。

  在nginx中down掉這台tomcat，用戶端那邊測試一切OK。問題到此解決。至于為什麼這台有問題，是白天開發直接動過tomcat的代碼。問題隻能白天上班來配合查找代碼的問題。

四、總結

  經過此次的排錯，總結一下:

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

  2、善于利用各應用程式的日志進行錯誤跟蹤。

  3、還是要對各應用做到了然于心，對于各類報錯盡量知道大概是什麼問題。從哪裡排查。

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

本文轉自Mr_陳 51CTO部落格，原文連結：http://blog.51cto.com/chenpipi/1682450，如需轉載請自行聯系原作者