【網絡排查】 揮手：Nginx日志報connection reset by peer是怎么回事？

我們經常看到Nginx 的日志里面，可能就有 connection reset by peer 這種報錯。“連接被對端 reset（重置）”，這個字面上的意思是看明白了。但是，心里不免發毛：

• 這個 reset 會影響我們的業務嗎，這次事務到底有沒有成功呢?
• 這個 reset 發生在具體什么階段，屬於 TCP 的正常斷連嗎？
• 我們要怎么做才能避免這種 reset 呢？

先，你需要理解下 connection reset by peer 的含義。熟悉 TCP 的話，你應該會想到這大概是對端（peer）回復了 TCP RST（也就是這里的 reset），終止了一次 TCP 連接。其實，這也是我們做網絡排查的第一個要點：把應用層的信息，“翻譯”成傳輸層和網絡層的信息。

這里我說的“應用層信息”，可能是以下這些：

• 應用層日志，包括成功日志、報錯日志，等等；
• 應用層性能數據，比如 RPS（每秒請求數），transaction time（處理時間）等；
• 應用層載荷，比如 HTTP 請求和響應的 header、body 等。

而“傳輸層 / 網絡層信息”，可能是以下種種：

• 傳輸層：TCP 序列號（Sequence Number）、確認號（Acknowledge Number）、MSS、接收窗口（Receive Window）、擁塞窗口（Congestion Window）、時延（Latency）、重復確認（DupAck）、選擇性確認（Selective Ack）、重傳（Retransmission）、丟包（Packet loss）等。
• 網絡層：IP 的 TTL、MTU、跳數（hops）、路由表等。

可見，這兩大類（應用 vs 網絡）信息的視角和度量標准完全不同，所以幾乎沒辦法直接掛鈎。而這，也就造成了問題排查方面的兩大鴻溝。

• 應用現象跟網絡現象之間的鴻溝：你可能看得懂應用層的日志，但是不知道網絡上具體發生了什么。
• 工具提示跟協議理解之間的鴻溝：你看得懂 Wireshark、tcpdump 這類工具的輸出信息的含義，但就是無法真正地把它們跟你對協議的理解對應起來

你需要具備把兩大鴻溝填平的能力，有了這個能力，你也就有了能把兩大類信息（應用信息和網絡信息）聯通起來的“翻譯”的能力。這正是網絡排查的核心能力。

 

案例 1：connection reset by peer?

大致應用日志是這樣的：

2015/12/01 15:49:48 [info] 20521#0: *55077498 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/weixin/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/weixin/notify_url.htm", host: "manager.example.com"
2015/12/01 15:49:54 [info] 20523#0: *55077722 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/app/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/app/notify_url.htm", host: "manager.example.com"
2015/12/01 15:49:54 [info] 20523#0: *55077710 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/app/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/app/notify_url.htm", host: "manager.example.com"
2015/12/01 15:49:58 [info] 20522#0: *55077946 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/app/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/app/notify_url.htm", host: "manager.example.com"
2015/12/01 15:49:58 [info] 20522#0: *55077965 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/app/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/app/notify_url.htm", host: "manager.example.com"

這里我們理解一下應用日志相關信息：

• recv() failed：這里的 recv() 是一個系統調用，也就是 Linux 網絡編程接口。它的作用呢，看字面就很容易理解，就是用來接收數據的。我們可以直接 man recv，看到這個系統調用的詳細信息，也包括它的各種異常狀態碼。
• 104：這個數字也是跟系統調用有關的，它就是 recv() 調用出現異常時的一個狀態碼，這是操作系統給出的。在 Linux 系統里，104 對應的是 ECONNRESET，也正是一個 TCP 連接被 RST 報文異常關閉的情況。
• upstream：在 Nginx 等反向代理軟件的術語里，upstream 是指后端的服務器。也就是說，客戶端把請求發到 Nginx，Nginx 會把請求轉發到 upstream，等后者回復 HTTP 響應后，Nginx 把這個響應回復給客戶端。注意，這里的“客戶端 <->Nginx”和“Nginx<->upstream”是兩條獨立的 TCP 連接，也就是下圖這樣：

 

 

 這里我們要找到 TCP RST 報文，所以使用下面的過濾條件：

ip.addr eq 10.255.252.31 and tcp.flags.reset eq 1 and !(tcp.seq eq 1 or tcp.ack eq 1)

• tcp.flags.reset eq 1  rst標志位為1的報文

• !(tcp.seq eq 1 or tcp.ack eq 1) 同時rst和ack標志位不能同時為1的報文

 

 

 

為了找到它們，我們需要再增加一些明確的搜索條件。還記得我提到過的兩大鴻溝嗎？一個是應用現象跟網絡現象之間的鴻溝，一個是工具提示跟協議理解之間的鴻溝。現在為了跨越第一個鴻溝，我們需要把搜索條件落實具體，針對當前案例來說，就是基於以下條件尋找數據包：

• 既然這些網絡報文跟應用層的事務有直接關系，那么報文中應該就包含了請求相關的數據，比如字符串、數值等。當然，這個前提是數據本身沒有做過特定的編碼，否則的話，報文中的二進制數據，跟應用層解碼后看到的數據就會完全不同。
• 這些報文的發送時間，應該跟日志的時間是吻合的。

對於條件 1，我們可以利用 Nginx 日志中的 URL 等信息；對於條件 2，我們就要利用日志的時間。其實，在開頭部分展示的 Nginx 日志中，就有明確的時間（2015/12/01 15:49:48），雖然只是精確到秒，但很多時候已經足以幫助我們進一步縮小范圍了。

那么，在 Wireshark 中搜索“特定時間段內的報文”，又要如何做到呢？這就是我要介紹給你的又一個搜索技巧：使用 frame.time 過濾器。比如下面這樣：

frame.time >="dec 01, 2015 15:49:48" and frame.time <="dec 01, 2015 15:49:49"

這就可以幫助我們定位到跟上面 Nginx 日志中，第一條日志的時間匹配的報文了。為了方便你理解，我直接把這條日志復制到這里給你參考：

2015/12/01 15:49:48 [info] 20521#0: *55077498 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/weixin/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/weixin/notify_url.htm", host: "manager.example.com"

我們再結合前面的搜索條件，就得到了下面這個更加精確的過濾條件：

frame.time >="dec 01, 2015 15:49:48" and frame.time <="dec 01, 2015 15:49:49" and ip.addr eq 10.255.252.31 and tcp.flags.reset eq 1 and !(tcp.seq eq 1 or tcp.ack eq 1)

這次我們終於非常成功地鎖定到只有 3 個 RST 報文了：

 

 

 我們先來看看，11393 號報文所屬的流是什么情況？

 

 

 原來，11448 跟 11450 是在同一個流里面的。現在清楚了，3 個 RST，分別屬於 2 個 HTTP 事務。

你再仔細對比一下兩個圖中的紅框部分，是不是不一樣？它們分別是對應了一個 URL 里帶“weixin”字符串的請求，和一個 URL 里帶“app”字符串的請求。那么，在這個時間點（15:49:48）對應的日志是關於哪一個 URL 的呢？

2015/12/01 15:49:48 [info] 20521#0: *55077498 recv() failed (104: Connection reset by peer) while sending to client, client: 10.255.252.31, server: manager.example.com, request: "POST /WebPageAlipay/weixin/notify_url.htm HTTP/1.1", upstream: "http:/10.4.36.207:8080/WebPageAlipay/weixin/notify_url.htm", host: "manager.example.com"

你只要往右拖動一下鼠標，就能看到 POST URL 里的“weixin”字符串了。而包號 11448 和 11450 這兩個 RST 所在的 TCP 流的請求，也是帶“weixin”字符串的，所以它們就是匹配上面這條日志的 RST！如果你還沒有完全理解，我這里幫你小結一下，為什么我們可以確定這個 TCP 流就是對應這條日志的，主要三點原因：

• 時間吻合；
• RST 行為吻合；
• URL 路徑吻合。

根據HTTP過程和數據包情況可以是一下過程

 

 

 

也就是說，握手和 HTTP POST 請求和響應都正常，但是客戶端在對 HTTP 200 這個響應做了 ACK 后，隨即發送了 RST+ACK，而正是這個行為破壞了正常的 TCP 四次揮手。也正是

這個 RST，導致服務端 Nginx 的 recv() 調用收到了 ECONNRESET 報錯，從而進入了 Nginx 日志，成為一條 connection reset by peer。

這個對應用產生了什么影響呢？對於服務端來說，表面上至少是記錄了一次報錯日志。但是有意思的是，這個 POST 還是成功了，已經被正常處理完了，要不然 Nginx 也不會回復 HTTP 200。

對於客戶端呢？還不好說，因為我們並沒有客戶端的日志，也不排除客戶端認為這次是失敗，可能會有重試等等。

我們把這個結論告訴給了客戶，他們懸着的心稍稍放下了：至少 POST 的數據都被服務端處理了。當然，他們還需要查找客戶端代碼的問題，把這個不正常的 RST 行為給修復掉，但是至少已經不用擔心數據是否完整、事務是否正常了。

 

我們現在就可以回答了：

• 這個 reset 是否影響業務，還要繼續查客戶端應用，但服務端事務是成功被處理了。
• 這個 reset 發生在事務處理完成后，但不屬於 TCP 正常斷連，還需要繼續查客戶端代碼問題。
• 要避免這種 reset，需要客戶端代碼進行修復。

一個 FIN 就完成了 TCP 揮手？

 

 

 我在圖上沒有用“客戶端”和“服務端”這種名稱，而是叫“發起端”和“接收端”。這是因為，TCP 的揮手是任意一端都可以主動發起的。也就是說，揮手的發起權並不固定給客戶端或者服務端。這跟 TCP 握手不同：握手是客戶端發起的。或者換個說法：發起握手的就是客戶端。在握手階段，角色分工十分明確。

可是有一次，一個客戶向我報告這么一個奇怪的現象：他們偶然發現，他們的應用在 TCP 關閉階段，只有一個 FIN，而不是兩個 FIN。這好像不符合常理啊。我也覺得有意思，就一起看了他們這個抓包文件：

 

 確實奇怪，真的只有一個 FIN。這兩端的操作系統竟然能容忍這種事情發生？TCP 里一個報文可以搭另一個報文的順風車（Piggybacking），以提高 TCP 傳輸的運載效率。所以，TCP 揮手倒不是一定要四個報文，Piggybacking 后，就可能是 3 個報文了。看起來就類似三次揮手。

那這次的案例，我們在 Wireshark 中看到了后兩個報文，即接收端回復的 FIN+ACK 和發起端的最后一個 ACK。那么，第一個 FIN 在哪里呢？從 Wireshark 的截圖中，確實看不出來。當然，從 Wireshark 的圖里，我們甚至可以認為，這次連接是服務端發起的，它發送了 FIN+ACK，而客戶端只回復了一個 ACK，這條連接就結束了。這樣的解讀更加詭異，卻也符合 Wireshark 的展示。

 

 但是，Wireshark 的主界面還有個特點，就是當它的 Information 列展示的是應用層信息時，這個報文的 TCP 層面的控制信息就不顯示了。所以，上面的 POST 請求報文，其 Information 列就是 POST 方法加上具體的 URL。它的 TCP 信息，包括序列號、確認號、標志位等，都需要到詳情里面去找。我們先選中這個 POST 報文，然后到界面中間的 TCP 詳情部分去看看：

 

 原來，第一個 FIN 控制報文，並沒有像常規的那樣單獨出現，而是合並（Piggybacking）在 POST 報文里！所以，整個揮手過程，其實依然十分標准，完全遵循了協議規范。僅僅是因為 Wireshark 的顯示問題，帶來了一場小小的誤會。雖然還有一個“為什么沒有 HTTP 響應報文”的問題，但是 TCP 揮手方面的問題，已經得到了合理的解釋了。