Golang之HTTP服務『假死』問題排查

時間 2020-11-11

標籤 git github web curl tcp 函數學習 url debug 欄目 Go 简体版

原文原文鏈接

問題描述

下午15點左右，QA反饋灰度環境大量請求超時。kibana查詢灰度網關日誌，確實存在部分請求響應時間超過60秒，HTTP狀態碼504。進一步分析日誌，全部504請求的上游地址都是xxxx:80。git

目前該服務部署了兩套環境，k8s + kvm，k8s環境上游ingress（即Nginx）端口80，kvm環境上游Golang服務端口19001。且，k8s環境該服務只部署一個pod。是單單k8s環境服務有問題嗎？github

登陸到k8s服務終端，手動curl請求（healthCheck接口，沒有複雜的業務處理，直接返回數據），發現請求沒有任何響應，且一直阻塞。很大機率是該Golang服務有問題了。web

排查過程

healthCheck接口邏輯很是的簡單，爲何會阻塞呢？服務沒有接收到該請求嗎？tcpdump抓包看看：curl

//xxxx爲k8s入口ingress地址
curl http://xxxx/v1/healthCheck -H "Host:studentlive.xueersi.com"

//三次握手
10:20:21.940968 IP xxxx.40970 > server.19001: Flags [S], seq 3201212889, win 29200, length 0
10:20:21.941003 IP server.19001 > xxxx.40970: Flags [S.], seq 1905160768, ack 3201212890, win 28960, length 0
10:20:21.941175 IP xxxx.40970 > server.19001: Flags [.], ack 1905160769, win 58, length 0

//發送HTTP請求數據
10:20:21.941219 IP xxxx.40970 > server.19001: Flags [P.], seq 3201212890:3201213201, ack 1905160769, win 58, length 311
10:20:21.941223 IP server.19001 > xxxx.40970: Flags [.], ack 3201213201, win 59, length 0

//客戶端主動斷開鏈接
10:21:21.945740 IP xxxx.40970 > server.19001: Flags [F.], seq 3201213201, ack 1905160769, win 58, length 0
10:21:21.985062 IP server.19001 > xxxx.40970: Flags [.], ack 3201213202, win 59, length 0

能夠看到，三次握手成功，客戶端發送了HTTP數據，服務端也正常返回ACk；可是沒下文了，客戶端等待60秒後，主動斷開了鏈接。（Nginx配置：proxy_read_timeout=60秒）。tcp

服務端接收到客戶端請求爲何沒有響應呢？能夠dlv跟蹤調試請求處理流程，看看是在哪個環節阻塞了；另外，服務都開啓了pprof，能夠先看看當前服務的狀態。函數

curl http://localhost:17009/debug/pprof/

<td>16391</td><td><a href=goroutine?debug&#61;1>goroutine</a></td>
……

協程數目很是多，有1.6w，而灰度環境目前流量已切走；理論上不該該存在這麼多協程的。學習

繼續使用pprof查看協程統計詳細信息：ui

go tool pprof http://localhost:17009/debug/pprof/goroutine

(pprof) traces
----------+-------------------------------------------------------
7978 runtime.gopark
     runtime.goparkunlock
     runtime.chansend
     runtime.chansend1
     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.(*FileLogTraceWriter).LogWrite
     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.Logger.LogTraceMap
     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.LogTraceMap
     git.100tal.com/wangxiao_go_lib/xesLogger/builders.(*TraceBuilder).LoggerX
     git.100tal.com/wangxiao_go_lib/xesLogger.Ix
     git.100tal.com/wangxiao_go_lib/xesGoKit/middleware.Logger.func1
     github.com/gin-gonic/gin.(*Context).Next
     github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
     github.com/gin-gonic/gin.(*Engine).ServeHTTP
     net/http.serverHandler.ServeHTTP
     net/http.(*conn).serve

能夠看到，大量協程在寫日誌（LogWrite）時候，阻塞了（管道寫阻塞runtime.chansend），觸發了協程切換。url

代碼Review

經過上面的排查，已經能夠基本確認請求是阻塞在寫日誌這裏了；下面須要排查下寫日誌爲何會阻塞請求呢。寫日誌的邏輯是這樣的：debug

//寫日誌方法；只是寫管道
func (w *FileLogTraceWriter) LogWrite(rec *LogRecord) {
    w.rec <- rec
}

func NewFileLogTraceWriter(fname string, rotate bool) *FileLogTraceWriter {
   
   //子協程，從管道讀取數據寫入buffer
    go func() {
        for {
            select {
            case rec, ok := <-w.rec:
            }
        }
    }
    
    //子協程，從buffer讀取數據寫入文件
    go func() {
        for {
            select {
            case lb, ok := <-w.out:
            }
        }
    }
}

咱們看到，HTTP處理請求，在寫日誌時候，調用LogWrite方法將日誌寫入管道。而在初始化FileLogTraceWriter時候，會啓動子協程從管道中死循環讀取日誌數據。日誌寫入管道阻塞了，頗有多是這個子協程出異常了。

查找這兩個子協程堆棧：

1   runtime.gopark
    runtime.selectgo
    git.100tal.com/wangxiao_go_lib/xesLogger/log4go.NewFileLogTraceWriter.func2

NewFileLogTraceWriter.func2阻塞在select處；NewFileLogTraceWriter.func1協程不存在。

問題明白了，從管道中消費日誌的子協程由於某些緣由退出了。該協程有兩處邏輯，在出現錯誤時候，直接return，會致使協程的結束。只惋惜灰度環境沒有采集日誌，時間太長日誌都不存在了，沒法肯定協程退出的真正緣由。

另外，查看日誌文件的狀態等都是正常的：

//日誌路徑，權限等正常
# ll /home/logs/xeslog/talcamp/talcamp.log
-rw-r--r--    1 root     root             0 Nov 10 00:00 /home/logs/xeslog/talcamp/talcamp.log

//服務正常打開日誌文件
# lsof -p 67 | grep "talcamp.log"
9       /home/www/talcamp/bin/talcamp   /home/logs/xeslog/talcamp/talcamp.log

非阻塞改造

HTTP請求處理協程，經過寫管道方式寫日誌，就是爲了避免阻塞本身。可是發現，當管道消費者異常時候，仍是會形成阻塞。web服務，寫日誌是必然的同時也是非必須的，如何才能保障寫日誌不會阻塞HTTP請求處理呢？其實寫管道也能夠是非阻塞方式的：

有興趣的能夠查看runtime/chan.go文件學習。

// 非阻塞寫實現
// compiler implements
//
//    select {
//    case c <- v:
//        ... foo
//    default:
//        ... bar
//    }
//
// as
//
//    if selectnbsend(c, v) {
//        ... foo
//    } else {
//        ... bar
//    }
//
func selectnbsend(c *hchan, elem unsafe.Pointer) (selected bool) {
    return chansend(c, elem, false, getcallerpc())
}


// 非阻塞讀實現
//compiler implements
//
//    select {
//    case v = <-c:
//        ... foo
//    default:
//        ... bar
//    }
//
// as
//
//    if selectnbrecv(&v, c) {
//        ... foo
//    } else {
//        ... bar
//    }
//
func selectnbrecv(elem unsafe.Pointer, c *hchan) (selected bool) {
    selected, _ = chanrecv(c, elem, false)
    return
}

查看Golang SDK源碼，基於select能夠實現管道的非阻塞讀寫（chanrecv與chansend函數，第三個參數標識是否阻塞當前協程）。另外，咱們也能夠稍加改造，實現管道帶超時時間的讀寫。