記一次kubernetes叢集異常: kubelet連線apiserver超時

gaorong404發表於2019-05-28

Background

kubernetes是master-slave結構,master node是叢集的大腦, 當master node發生故障時整個叢集都"out of controll"。master node中最重要的當屬apiserver元件, 它負責處理所有請求, 並持久化狀態到etcd。 一般我們會部署多份apiserver實現高可用。官方建議在多個apiserver前面部署一個LB進行負載均衡,當其中一臺apiserver發生故障之後,LB 自動將流量切換到其他例項上面。這樣雖然簡單,但是也引入了額外的依賴,如果LB發生故障將會導致全部apiserver不可用。我們知道在kubernetes中node節點上kubelet與apiserver心跳超時後, controller-manager會將該node狀態置為notReady, 隨後驅逐其上的pod,使這些pod在其他地方重建。 所以當LB發生故障時, 叢集中所有的node都會變為notReady狀態,進而導致大規模的pod驅逐。

故障發生

無獨有偶,這樣的事情偏偏被我們碰到了,接到線上大量node not ready的報警後,立刻上線檢視,發現所有的node kubelet都報如下錯誤:

E0415 17:03:11.351872   16624 kubelet_node_status.go:374] Error updating node status, will retry: error getting node "k8s-slave88": Get https://10.13.10.12:6443/api/v1/nodes/k8s-slave88?resourceVersion=0&timeout=5s: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
E0415 17:03:16.352108   16624 kubelet_node_status.go:374] Error updating node status, will retry: error getting node "k8s-slave88": Get https://10.13.10.12:6443/api/v1/nodes/k8s-slave88?timeout=5s: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
E0415 17:03:21.352335   16624 kubelet_node_status.go:374] Error updating node status, will retry: error getting node "k8s-slave88": Get https://10.13.10.12:6443/api/v1/nodes/k8s-slave88?timeout=5s: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
E0415 17:03:26.352548   16624 kubelet_node_status.go:374] Error updating node status, will retry: error getting node "k8s-slave88": Get https://10.13.10.12:6443/api/v1/nodes/k8s-slave88?timeout=5s: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
E0415 17:03:31.352790   16624 kubelet_node_status.go:374] Error updating node status, will retry: error getting node "k8s-slave88": Get https://10.13.10.12:6443/api/v1/nodes/k8s-slave88?timeout=5s: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
E0415 17:03:31.352810   16624 kubelet_node_status.go:366] Unable to update node status: update node status exceeds retry count

日誌中顯示的10.13.10.12是LB的地址。通過這個日誌判斷是kubelet連線apiserver失敗,初步懷疑是網路故障,手動telnet 10.13.10.12 6443後發現一切正常,這就比較奇怪了,明明網路通訊正常, kubelet為什麼連不上apiserver? 趕緊用tcpdump抓包分析了一下,發現kubelet不斷地給apiservre傳送包卻沒有收到對端的ACK,登入master檢視apiserver服務也一切正常。後來同事發現重啟kubelet就好了,為了儘快解決問題只能把kubelet全部重啟了,後面再慢慢定位問題。

定位問題

叢集恢復之後,發現有故障通報LB發生了故障,聯絡了相關同學發現時間點剛好相符,懷疑是因為LB異常導致kubelet無法連線apiserver。 經過溝通後發現: LB會為其轉發的每一個connection維護一些資料結構,當新的一臺LB server上線之後會均攤一部分原來的流量,但是在其維護的資料結構中找不到該connection的記錄就會認為這個請求非法,直接DROP掉。 類似的事確實還發生不少,在kubernetes的isuse裡有不少這樣的案例,甚至需要公有云的的LB也會有這樣的問題,參見這個kubernetes#41916, kubernetes#48638, kubernetes-incubator/kube-aws#598。大概明白原因之後, push LB的同學改進的同時, kubelet也應該做一些改進: 當kubelet連線apiserver超時之後, 應該reset 掉連線, 進行重試。簡單做了一個測試,使用iptables規則drop掉kubelet發出的流量來模擬網路異常:

首先確保kubelet 與apiserver連線正常, 執行netstat -antpl | grep 6443可以看到kubelet與apiserver 10.132.106.115:6443連線正常

[root@c4-jm-i1-k8stest03 ~]# netstat -antpl  |grep kubelet
tcp        0      0 127.0.0.1:10248         0.0.0.0:*               LISTEN      23665/./kubelet     
tcp        0      0 10.162.1.26:63876       10.132.106.115:6443     ESTABLISHED 23665/./kubelet     
tcp6       0      0 :::4194                 :::*                    LISTEN      23665/./kubelet     
tcp6       0      0 :::10250                :::*                    LISTEN      23665/./kubelet     
tcp6       0      0 :::10255                :::*                    LISTEN      23665/./kubelet     
tcp6       0      0 10.162.1.26:10250       10.132.1.30:61218       ESTABLISHED 23665/./kubelet     

這時候執行iptables -I OUTPUT -p tcp --sport 63876 -j DROP將kubelet發出的包丟掉,模擬網路故障,此時可以看到netstat的輸出中該連線的Send-Q正在逐步增加,並且kubelet也列印出日誌顯示無法連線,

[root@c4-jm-i1-k8stest03 ~]# netstat -antpl  |grep kubelet
tcp        0      0 127.0.0.1:10248         0.0.0.0:*               LISTEN      23665/./kubelet     
tcp        0    928 10.162.1.26:63876       10.132.106.115:6443     ESTABLISHED 23665/./kubelet  

連線被hang住了,重啟kubelet之後,一切又恢復了。這個現象和當時發生故障的情況一模一樣:連線異常導致kubelet心跳超時,重啟kubelet後會新建連線, 恢復正常心跳。因為我們當前採用的kubernetes版本是v1.10.2,下載master分支的程式碼編譯試了下,也是有這個問題的,感覺這個問題一直存在。

艱難的修復

接下來就是怎麼修復這個問題了。網上找了一下相關的issue, 首先找到的是kubernetes/client-go#374這個issue,上面描述的情況和我們碰到的很相似,有人說是因為使用了HTTP/2.0協議(以下簡稱h2),查詢了一下kubelet的原始碼,發現kubelet預設是使用h2協議,具體的程式碼實現在SetTransportDefaults這個函式中(點選閱讀原始碼)。可以通過設定環境變數DISABLE_HTTP2來禁用h2,簡單驗證了一下: 顯式設定該環境變數禁用h2後, 讓連線使用http1.1確實沒有這個問題了。 查閱文件發現這是http1.1與http2.0的差異:在http1.1中,預設採用keep-alive複用網路連線,發起新的請求時, 如果當前有閒置的連線就會複用該連線, 如果沒有則新建一個連線。當kubelet連線異常時,老的連線被佔用,一直hang在等待對端響應,kubelet在下一次心跳週期,因為沒有可用連線就會新建一個,只要新連線正常通訊,心跳包就可以正常傳送。在h2中,為了提高網路效能,一個主機只建立一個連線,所有的請求都通過該連線進行,預設情況下,即使網路異常,他還是重用這個連線,直到作業系統將連線關閉,而作業系統關閉殭屍連線的時間預設是十幾分鍾,具體的時間可以調整系統引數net.ipv4.tcp_retries2, net.ipv4.tcp_keepalive_time, net.ipv4.tcp_keepalive_probes, net.ipv4.tcp_keepalive_intvl。(在上面issue中的回覆中,確實有人這麼做,通過調整作業系統斷開異常連線的時間實現快速恢復)。h2主動探測連線故障是通過傳送Ping frame來實現,這是一個優先順序比較高並且payload很少的包,網路正常時是可以快速返回, 該frame預設不會傳送, 需要顯式設定才會傳送。 在一些grpc等要求可靠性比較高的通訊框架中都實現了Ping frame,在gRPC On HTTP/2: Engineering A Robust, High Performance Protocol中談到

The less clean version is where the endpoint dies or hangs without informing the client. In this case, TCP might undergo retry for as long as 10 minutes before the connection is considered failed. Of course, failing to recognize that the connection is dead for 10 minutes is unacceptable. gRPC solves this problem using HTTP/2 semantics: when configured using KeepAlive, gRPC will periodically send HTTP/2 PING frames. These frames bypass flow control and are used to establish whether the connection is alive. If a PING response does not return within a timely fashion, gRPC will consider the connection failed, close the connection, and begin reconnecting (as described above).

可以看到grpc同樣存在這樣的問題,為了快速識別故障連線並恢復採用了Ping frame。 但是目前kubernetes所建立的連線中並沒有實現Ping frame, 導致了無法及時發現連線異常並自愈。

社群那個issue已經開了很長時間好像並沒有解決的痕跡,還得自己想辦法。我們知道一個http.Client本身其實只做了一些http協議的處理,底層的通訊是交給Transport來實現, Transport決定如何根據一個requst返回對應的reponse。在kubernetes client-go中關於Transporth2的設定只有這一個函式

// SetTransportDefaults applies the defaults from http.DefaultTransport
// for the Proxy, Dial, and TLSHandshakeTimeout fields if unset
func SetTransportDefaults(t *http.Transport) *http.Transport {
    t = SetOldTransportDefaults(t)
    // Allow clients to disable http2 if needed.
    if s := os.Getenv("DISABLE_HTTP2"); len(s) > 0 {
        klog.Infof("HTTP2 has been explicitly disabled")
    } else {
        if err := http2.ConfigureTransport(t); err != nil {
            klog.Warningf("Transport failed http2 configuration: %v", err)
        }
    }
    return t
}

只是呼叫了http2.ConfigureTransport來設定transport支援h2。這一句程式碼似乎太過簡單,並沒有任何Ping frame相關的處理邏輯。查了下golang標準庫中TransportPing frame相關的方法,令人失望的是,當前golang 對於一個tcp連線的抽象ClientConn已經支援傳送Ping framle,但是連線是交由連線池clientConnPool管理的, 該結構是個內部的私有結構體,我們沒法直接操作,封裝連線池的Transport也沒有暴露任何的介面來實現設定連線池中的所有連線定期傳送Ping frame。如果我們想實現這個功能就必須自定義一個Transport並實現一個連線池,要實現一個穩定可靠的Transport似乎並不容易。只能求助golang社群看有沒有解決方案, 提交了一個issue後:x/net/http2: make Transport occasionally send PING frames to server #31643, 很快就有人回覆並提交了PR,檢視了一下,實現還是比較簡單的,於是基於這個PR實現了clinet-goPing frame的探測。

峰迴路轉

開發完畢準備上線的時候,想趁這次修復升級一下kubernetes版本到v1.10.11,一般patch release是保證相容的。在測試v1.10.11的時候驚奇的發現,即使不改任何程式碼, 這個問題也沒辦法復現了。說明在v1.10.2中是有問題的,在v1.10.11中恢復了,接著在master中又引入了這個問題,看來還得需要仔細閱讀一下這部分程式碼了,到底是發生了什麼。

經過閱讀程式碼,發現這個邏輯曾經在track/close kubelet->API connections on heartbeat failure #63492這裡修復過,並且backport到1.10.3的程式碼中,當連線異常時會會呼叫closeAllConns強制關閉掉所有的連線使其重建。隨後在Restore bootstrap in the background with fix to preserve kubeadm behavior #71174這裡又引入了regression:將closeAllConns置為nil,導致連線無法正常關閉。明白了這個邏輯之後修改就簡單了,將closeAllConns再置為正確的值即可,給官方提交了一個pr: kubelet: fix fail to close kubelet->API connections on heartbeat failure #78016。官方很樂意就接受了, 並backport到了1.14版本中。 至此這個就算完全修復了, 當然可以通過上文提到的給h2增加Ping frame的方式解決該問題, 這是這種方案可能比較複雜, 修復時間比較長。

相關文章