使用 nginx 作反向代理，啟用 keepalive 時，遇到 502 錯誤的調查過程

1.現象

　　結論見 《kubernetes ingress-nginx 啟用 upstream 長連接，需要注意，否則容易 502》。nginx 的訪問日志間歇性出現 502 響應，查看 nginx 的 error.log，發現是 upstream 返回了 reset：

2019/06/13 04:57:54 [error] 3429#3429: *21983075 upstream prematurely closed connection while reading 
response header from upstream, client: 10.19.167.120, server: XXXX.com, request: "POST XXXX HTTP/1.0",
upstream: "http://11.0.29.4:8080/XXXXXX", host: "XXXX.com"
 
2019/06/13 04:58:34 [error] 3063#3063: *21989359 recv() failed (104: Connection reset by peer) while 
reading response header from upstream, client: 10.19.138.139, server: XXXX.com, request: 
"POST /api/v1/XXXX HTTP/1.1", upstream: "http://11.0.145.9:8080/api/v1/XXXX", host: "XXXX.com"

 

2.調查

　　在 nginx 上抓包，nginx 向 upstream 發送請求后，upstream 直接返回 reset，nginx 回應 502，觸發 reset 的請求的發送時間比上次晚了 1 分鍾以上：

　　

　　檢查其它正常響應的連接，發現服務端會在連接閑置 1 分20 秒的時候，主動斷開連接：

　　

　　奇怪的是 nginx 設置的 keepalive_timeout 為 60 秒，為什么不是 nginx 主動斷開連接？

 

3.驗證第一個假設：服務端 idle 先超時會引發 reset

　　猜測 upstream 對應的服務端也設置了超時時間，並且比 nginx 先超時，因此出現了服務端率先斷開連接情況。如果服務端斷開連接時，nginx 正好向 upstream 發送了請求，就可能出現 reset 的情況。

　　部署一個服務端容器，服務端的 idle 超時設置為 10 秒，小於 nginx 中配置的 keepalive_timeout （60秒）。用 httpperf 模擬 100 個會話，每個會話以每間隔 9 秒發送 100 個請求的方式累計發送 300 個請求，會話創建速率是每秒 10 個。

httperf --server webshell.example.test --port 80 --wsess 100,300,9 --burst-len 100 --rate 10
./httperf --server webshell.example.test --port 80 --wsess 1,256,9 --burst-len 128 --rate 1

　　遺憾的是 httperf 太老舊支持的量太少，沒能復現出來。假設的場景本身也很難復現，必須恰好在連接因為超時關閉時發送請求，比較難復現。

　　另外找到三篇文章都在討論這個問題：

　　1.104: Connection reset by peer while reading response header from upstream

　　2.HTTP 502 response generated by a proxy after it tries to send data upstream to a partially closed connection (reset packet)

　　3.Analyze ‘Connection reset’ error in nginx upstream with keep-alive enabled

 

4.發現新情況

　　有用戶反應能夠穩定復現 502，且是在壓測期間發現的，這就奇怪了。idle 超時導致的 502 應該很難出現，能穩定復現 502 肯定是有其它原因。

　　在繼續調查的過程中，首先想到的是「長連接中的最大請求數」，服務端會不會設置了單個連接中能夠處理的請求數上限，並且該上限小於 nginx 中的配置？

　　公司的業務系統主要是 tomcat 服務，因此優先調查 tomcat 的配置，發現了下面的參數：

　　tomcat 默認每個連接中最多 100 個請求，而 nginx 中配置的 keepalive_requests 超過了 100，這會不會是問題根源？需要測試驗證一下。

　　同時發現 tomcat 默認的 idle 超時時間是 60s，和前面提出的超時假設能夠相呼應，tomcat 7 和 tomcat 8 的使用的是相同的默認配置。Tomcat Config。

　　

 

5.驗證第二個假設：服務端率先斷開連接導致502

　　部署一個 tomcat 服務，idle 超時時間為 60s，maxKeepAliveRequests 為 100，nginx 的 idle 超時為 60s，keepalive_requests 為 2000，用下面的命令壓測：

./wrk -t 4  -c 10000 -d 90s http://ka-test-tomcat.example.test/ping

　　10000 並發壓測 90s 時，出現 502 響應：

　　然而從報文發現：服務端直接 reset 的連接數是 24 個，數量遠遠低於 502 響應的數量。

　　懷疑還有其它原因，檢查 nginx 發現大量下面的日志：

2019/06/17 09:35:46 [crit] 28805#28805: *9114394 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"
2019/06/17 09:35:46 [crit] 28806#28806: *9114649 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"
2019/06/17 09:35:46 [crit] 28804#28804: *9114172 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"

　　統計了一下，crit 日志數和 502 響應的數量級相同，斷定本次壓測中產生大部分 502 是 nginx 上的端口不足導致的，又發現了一種導致 502 原因：nginx 的端口耗盡 。

　　嘗試降低並發數量，排除端口耗盡的情況：

./wrk -t 4  -c 500 -d 300s http://ka-test-tomcat.example.test/ping

　　結果比較悲催，無論如何也沒有 502，檢查報文發現有少量服務端回應的 RST 報文，是在發起了 FIN 連接后再次回應的。而在多次壓測過程中，又的確出現過兩次總計100多條的 104: Connection reset by peer日志，但就是復現不出來，不知道是它們在什么情況下產生的……

 

6.新的發現

　　有點陷入僵局，回頭審視反應能夠穩定復現 502 的用戶的系統，最后一個請求與上一個請求的間隔時間是 2 秒。

　　這個 2 秒的時間差一開始帶來了困擾，也正是這個 2 秒的時間差，讓我懷疑之前的超時斷開假設不成立，調頭去查 maxKeepAliveRequests 的問題。

　　進入用戶的系統后，發現后端服務是用 Gunicorn 啟動的 python 服務，查閱 Gunicorn的配置，發現它默認的 keepalive 時間是 2秒，正好和報文中的情況對應。

　　也就是說，能夠穩定復現的 502 也是因為服務端先觸發 idle 超時，之所以能夠穩定觸發，因為后端服務的配置的超時時間只有 2秒，而請求端又恰好制造出靜默兩秒后發送下一個請求的場景。

　　超時斷開應該比超過 maxKeepAliveRequests 斷開更容易引發 502，因為超過 maxKeepAliveRequests 時，會在最后一個請求結束后立即發送 FIN 斷開連接，不容易與 nginx 正在轉發的請求「撞車」，而超時斷開可能在任意時刻發生，可能正好是 nginx 收到新的請求的時候，轉發新請求時與服務端關閉連接的操作「撞車」。

 

7.初步結論

　　根據日志和原理進行推測，提出兩個可能有效的方案：

　　1.nginx 的 keep-alive 的 idle 超時要小於 upstream 的 idle 超時；

　　2.nginx 的 keepalive_request 要小於 upstream 的相關設置。

　　以上兩個配置可以保證連接斷開都是 nginx 發起的，從而可以避免向一個已經關閉的連接發送請求。

 

8.轉載

https://www.lijiaocn.com/%E9%97%AE%E9%A2%98/2019/06/13/nginx-104-reset.html#本篇目錄