golang服務報錯: write: broken pipe的解決方案

2022-09-08 18:04:19

一、程式報錯

發現BSC節點報錯： write: broken pipe

2022/04/11 11:23:00 http: panic serving 172.31.34.109:32952: write tcp 172.31.6.64:9093->172.31.34.109:32952: write: broken pipe
goroutine 145578 [running]:
net/http.(*conn).serve.func1(0xc000399720)
   /usr/local/go/src/net/http/server.go:1824 +0x153
panic(0xfbc720, 0xc008f36be0)
   /usr/local/go/src/runtime/panic.go:971 +0x499
github.com/gin-gonic/gin/render.JSON.Render(...)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/render/json.go:56
github.com/gin-gonic/gin.(*Context).Render(0xc00621d600, 0xc8, 0x133ab98, 0xc00be29b10)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/context.go:927 +0x149
github.com/gin-gonic/gin.(*Context).JSON(...)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/context.go:970
bsc-wallet/router/apicommon.ReturnSuccessResponse(0xc00621d600, 0x0, 0x10c16c7, 0x7, 0xee3960, 0xc00ae84d20)
   /go/src/bsc-wallet/router/apicommon/common.go:38 +0xc5
bsc-wallet/router/handler.BlockInfo(0xc00621d600)
   /go/src/bsc-wallet/router/handler/wallethandler.go:395 +0x27e
github.com/gin-gonic/gin.(*Context).Next(...)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/context.go:168
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000120340, 0xc00621d600)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/gin.go:555 +0x2b0
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000120340, 0x133ec38, 0xc0067767e0, 0xc00621d500)
   /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/gin.go:511 +0x16b
net/http.serverHandler.ServeHTTP(0xc0001881c0, 0x133ec38, 0xc0067767e0, 0xc00621d500)
   /usr/local/go/src/net/http/server.go:2887 +0xa3
net/http.(*conn).serve(0xc000399720, 0x13405b8, 0xc0059e4a40)
   /usr/local/go/src/net/http/server.go:1952 +0x8cd
created by net/http.(*Server).Serve
   /usr/local/go/src/net/http/server.go:3013 +0x39b

這個錯誤的字面意思為：使用者端可能會在收到伺服器端響應之前斷開連線

二、問題原因

想到的問題原因可能是以下兩種原因：

伺服器端所在的伺服器，超過了最大連線數
使用者端在接收到伺服器端響應之前斷開連線

2.1 連線數過大

當我們有一些高並行請求量環境時，會遇到來自於系統級別的連線數限制問題，這是因為CentOS根據系統硬體資訊自己預設初始了一個限制連線數量，往往這個數量是我們遇到的問題，所以今天我們需要修改系統的預設值來達到我們需要的要求，解決一定的高並行產生的連線數問題。

使用以下命令檢視當前最大連線數：

# ulimit -n 
1024

臨時修改：該方法只在當前起作用

# ulimit -n 65535
# ulimit -n 
65535

永久修改：修改以下組態檔

# vim /etc/security/limits.conf

*       soft    nofile  65535
*       hard    nofile  65535
*       soft    nproc  65535
*       hard    nproc  65535

即便你使用limit -n 1024 等這樣的修改是無法其效果的，

以及各種修改可能都不起作用：

經過我們的大量研究最終解決了該問題

2.2 呼叫者在接收到伺服器端響應之前斷開連線

該問題可能是因為：client端獲取響應資料，突然異常退出或直接close連線。

client退出後，server將會傳送兩次資料，server第一次傳送給client，client返回給server RST。第二次在這個RST的連線上，server繼續傳送，出現broken pipe。即如下錯誤：

2022/04/11 12:27:53 http: panic serving 172.31.34.109:45842: write tcp 172.31.6.64:9093->172.31.34.109:45842: write: broken pipe

那麼此時就會出現兩個問題，server端遲遲沒有響應資料給client端，那麼也有可能是以下兩個原因：

server端去節點請求資料的時候，節點一直沒有返回連線數過高，請求需要排隊處理，可能有的請求還沒有處理完，就已經請求超時了

關於此問題已向client端進行求證，目前連線server端設定的超時時間是：連線超時：0.5秒，響應超時5秒

2.2.1 排查伺服器上的連線數

檢視系統連線數

# 獲取當前socket連線狀態統計資訊
# cat /proc/net/sockstat
sockets: used 1138
TCP: inuse 21 orphan 0 tw 0 alloc 786 mem 220
UDP: inuse 4 mem 2
UDPLITE: inuse 0
RAW: inuse 0
FRAG: inuse 0 memory 0

# 統計當前各種狀態的連線的數量的命令
# netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
CLOSE_WAIT 1020
ESTABLISHED 59

檢視埠範圍

# 允許系統開啟的埠範圍，用於向外連線的埠範圍
# cat /proc/sys/net/ipv4/ip_local_port_range
32768	60999

檢視檔案開啟數

# 檢視當前開啟檔案數 
# 如果執行緩慢，那麼執行結果顯示系統當前開啟檔案數500w
# lsof | wc -l
4792741

# 把當前開啟檔案列表儲存
# lsof>>/tmp/lsof.log  

# 檢視 5-6萬 行之間的資料
sed -n '50000,60000p' /tmp/lsof.log

結果，bsc，且沒有關閉：

COMMAND PID PPID USER PGID FD DEVICE SIZE NODE NAME
程序名稱程序識別符號父程序識別符號程序所有者程序所屬組檔案描述符指定磁碟名稱檔案大小索引節點開啟檔案的確切名稱
bsc-wallet 2105 2125 root 1872u sock 0,7 0t0 2800355 protocol: TCPv6
bsc-wallet 2105 2125 root 1873u sock 0,7 0t0 2802021 protocol: TCPv6
bsc-wallet 2105 2125 root 1874u sock 0,7 0t0 2765499 protocol: TCPv6
bsc-wallet 2105 2125 root 1875u sock 0,7 0t0 2803112 protocol: TCPv6
bsc-wallet 2105 2125 root 1876u sock 0,7 0t0 2769274 protocol: TCPv6
bsc-wallet 2105 2125 root 1877u sock 0,7 0t0 2803114 protocol: TCPv6
bsc-wallet 2105 2125 root 1878u sock 0,7 0t0 2770305 protocol: TCPv

2.2.2 檢視連線狀態為CLOSE_WAIT的連線情況

統計當前各種狀態的連線的數量的命令

#  netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
CLOSE_WAIT 1169
ESTABLISHED 84

檢視CLOSE_WAIT是哪臺伺服器請求的，以及請求數

# netstat -a |grep "CLOSE_WAIT"|awk '{print $5}'|awk -F '.' '{print $1}' |sort | uniq -c | sort -nr
   1382 ip-172-31-34-109

2.2.3 延時測試

可以看到情況為：另外一臺伺服器上面的服務（使用者端）請求到bsc-clinet（伺服器端）時，由於在他設定的超時時間內未返回請求資料，使用者端主動關閉了連線，導致伺服器端所在的伺服器出現大量關於該伺服器端的CLOSE_WAIT的連線狀態，最後伺服器端無法提供服務，報錯： write: broken pipe

伺服器端未出現 CLOSE_WAIT 時的響應時間及延時

伺服器端目前沒有CLOSE_WAIT連線狀態

#  netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
ESTABLISHED 21

獲取伺服器端請求響應時間

# curl -o /dev/null -s -w %{time_namelookup}::%{time_connect}::%{time_starttransfer}::%{time_total}::%{speed_download}"n" -d "number=16619272&sign=b8aaab58e4d73753430c473ba29756d3" http://127.0.0.1:9093/api/block/blockInfo

0.000::0.000::0.088::0.088::1572245.000

-o：把curl 返回的html、js 寫到垃圾回收站[ /dev/null]
-s：去掉所有狀態
-w：按照後面的格式寫出rt
time_namelookup：DNS 解析域名www.36nu.com的時間
time_commect：client和server端建立TCP 連線的時間
time_starttransfer：從client發出請求；到web的server 響應第一個位元組的時間
time_total：client發出請求；到web的server傳送會所有的相應資料的時間
speed_download：下週速度單位 byte/s

上面這條命令及返回結果可以這麼理解：
0.000: DNS 伺服器解析www.36nu.com 的時間單位是s
0.000: client發出請求，到c/s 建立TCP 的時間；裡面包括DNS解析的時間
0.088: client發出請求；到s響應發出第一個位元組開始的時間；包括前面的2個時間
0.088: client發出請求；到s把響應的資料全部傳送給client；並關閉connect的時間
1572245.000 ：下載資料的速度
建立TCP連線到server返回client第一個位元組的時間：0.088s – 0.000s = 0.088s
server把響應資料傳送給client的時間：0.088s – 0.088s = 0.000s

模擬使用者端超時時間：連線超時：1秒，響應超時5秒

使用CURL時，有兩個超時時間：一個是連線超時時間，另一個是資料傳輸的最大允許時間。

連線超時時間用–connect-timeout引數來指定，資料傳輸的最大允許時間用-m引數來指定。

# curl --connect-timeout 1 -m 5 -d "number=16619272&sign=b8aaab58e4d73753430c473ba29756d3" http://127.0.0.1:9093/api/block/blockInfo

超時時間沒有問題，可以返回資料

伺服器端出現 CLOSE_WAIT 時的響應時間及延時

伺服器端目有大量有CLOSE_WAIT連線狀態

# netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
CLOSE_WAIT 1185
ESTABLISHED 31

獲取伺服器端請求響應時間

# curl -o /dev/null -s -w %{time_namelookup}::%{time_connect}::%{time_starttransfer}::%{time_total}::%{speed_download}"n" -d "number=16619272&sign=b8aaab58e4d73753430c473ba29756d3" http://127.0.0.1:9093/api/block/blockInfo

無法請求到伺服器端

模擬使用者端超時

連線超時的話，出錯提示形如：