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

一、程序報錯

發現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/[email protected]/render/json.go:56
github.com/gin-gonic/gin.(*Context).Render(0xc00621d600, 0xc8, 0x133ab98, 0xc00be29b10)
    /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:927 +0x149
github.com/gin-gonic/gin.(*Context).JSON(…)
    /go/pkg/mod/github.com/gin-gonic/[email protected]/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/[email protected]/context.go:168
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000120340, 0xc00621d600)
    /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:555 +0x2b0
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000120340, 0x133ec38, 0xc0067767e0, 0xc00621d500)
    /go/pkg/mod/github.com/gin-gonic/[email protected]/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

無法請求到服務端

模擬客戶端超時

連接超時的話,出錯提示形如:

curl: (7) Failed connect to 127.0.0.1:9093; Connection refused

數據傳輸的最大允許時間超時的話,出錯提示形如:

curl: (28) Operation timed out after 30001 milliseconds with 0 out of -1 bytes received

三、解決方法

服務端出現大量的CLOSE_WAIT連接狀態,並且都是客戶端請求過來的,說明是客戶端主動關閉該連接,客戶端需要修改以下兩個問題:

  • 客戶端必須使用HTTP長連接池
  • 客戶端設置的響應超時時間5秒過於理想化,應修改該超時時間

當然,服務端此時需要請求其它服務獲取數據返回給客戶端,所以服務端請求時,也必須使用HTTP長連接池,延時可能也會影響該問題的出現,不過最主要的原因還是在客戶端上,先修改以上兩個問題即可。

希望大傢通過以上方式可以解決自己的實際需求,解決自己目前所遇到的問題。

到此這篇關於golang服務報錯: write: broken pipe解決的文章就介紹到這瞭,更多相關golang服務報錯write: broken pipe內容請搜索WalkonNet以前的文章或繼續瀏覽下面的相關文章希望大傢以後多多支持WalkonNet!

推薦閱讀: