筆者某天收到同事反饋,測試環境中 K8S 集羣進行滾動更新發布時未生效。經過 kube-apiserver 查看發現,對應的 Deployment 版本已是最新版,可是這個最新版本的 Pod 並未建立出來。node
針對該現象,咱們最開始猜想多是 kube-controller-manager 的 bug 致使,可是觀察 controller-manager 日誌並未發現明顯異常。第一次調高 controller-manager 的日誌等級並進行重啓操做以後,彷佛因爲 controller-manager 並無 watch 到這個更新事件,咱們仍然沒有發現問題所在。此時,觀察 kube-apiserver 日誌,一樣也沒有出現明顯異常。git
因而,再次調高日誌等級並重啓 kube-apiserver,詭異的事情發生了,以前的 Deployment 正常滾動更新了!程序員
因爲從 kube-apiserver 的日誌中一樣沒法提取出利於解決問題的有用信息,起初咱們只能猜想多是 kube-apiserver 的緩存更新異常致使的。正當咱們要從這個切入點出發去解決問題時,這位同事反饋了一個更詭異的問題——本身新建立的 Pod,經過 kubectl查詢 Pod 列表,忽然消失了!納尼?這是什麼騷操做?通過咱們屢次測試查詢發現,經過 kubectl 來 list pod 列表,該 pod 有時候能查到,有時候查不到。那麼問題來了,K8s api 的 list 操做是沒有緩存的,數據是 kube-apiserver 直接從 etcd 拉取返回給客戶端的,難道是 etcd 自己出了問題?github
衆所周知,etcd 自己是一個強一致性的 KV 存儲,在寫操做成功的狀況下,兩次讀請求不該該讀取到不同的數據。懷着不信邪的態度,咱們經過 etcdctl 直接查詢了 etcd 集羣狀態和集羣數據,返回結果顯示 3 個節點狀態都正常,且 RaftIndex 一致,觀察 etcd 的日誌也並未發現報錯信息,惟一可疑的地方是 3 個節點的 dbsize 差異較大。接着,咱們又將 client 訪問的 endpoint 指定爲不一樣節點地址來查詢每一個節點的 key 的數量,結果發現 3 個節點返回的 key 的數量不一致,甚至兩個不一樣節點上 Key 的數量差最大可達到幾千!而直接經過 etcdctl 查詢剛纔建立的 Pod,發現訪問某些 endpoint 可以查詢到該 pod,而訪問其餘 endpoint 則查不到。至此,基本能夠肯定 etcd 集羣的節點之間確實存在數據不一致現象。算法
強一致性的存儲忽然數據不一致了,這麼嚴重的問題,想必日誌裏確定會有所體現。然而,多是 etcd 開發者擔憂日誌太多會影響性能的緣故,etcd 的日誌打印的比較少,以致於咱們排查了 etcd 各個節點的日誌,也沒有發現有用的報錯日誌。甚至是在咱們調高日誌級別以後,仍沒有發現異常信息。後端
做爲一個21世紀的程序員,遇到這種詭異且暫時沒頭緒的問題,第一反應固然是先搜索一下啦,畢竟不會 StackOverFlow 的程序員不是好運維!搜索框輸入「etcd data inconsistent」 搜索發現,並非只有咱們遇到過該問題,以前也有其餘人向 etcd 社區反饋過相似問題,只是苦於沒有提供穩定的復現方式,最後都不了了之。如 issue:api
https://github.com/etcd-io/etcd/issues/9630緩存
https://github.com/etcd-io/etcd/issues/10407微信
https://github.com/etcd-io/etcd/issues/10594併發
https://github.com/etcd-io/etcd/issues/11643
因爲這個問題比較嚴重,會影響到數據的一致性,而咱們生產環境中當前使用了數百套 etcd 集羣,爲了不出現相似問題,咱們決定深刻定位一番。
在開始以前,爲方便讀者理解,這裏先簡單介紹下 etcd 的經常使用術語和基本讀寫原理。
術語表:
etcd 是一個強一致性的分佈式 KV 存儲,所謂強一致性,簡單來講就是一個寫操做成功後,從任何一個節點讀出來的數據都是最新值,而不會出現寫數據成功後讀不出來或者讀到舊數據的狀況。etcd 經過 raft 協議來實現 leader 選舉、配置變動以及保證數據讀寫的一致性。下面簡單介紹下 etcd 的讀寫流程:
寫數據流程(以 leader 節點爲例,見上圖):
讀數據流程:
初步驗證
一般集羣正常運行狀況下,若是沒有外部變動的話,通常不會出現這麼嚴重的問題。咱們查詢故障 etcd 集羣近幾天的發佈記錄時發現,故障前一天對該集羣進行的一次發佈中,因爲以前 dbsize 配置不合理,致使 db 被寫滿,集羣沒法寫入新的數據,爲此運維人員更新了集羣 dbsize 和 compaction 相關配置,並重啓了 etcd。重啓後,運維同窗繼續對 etcd 手動執行了 compact 和 defrag 操做,來壓縮 db 空間。
經過上述場景,咱們能夠初步判斷出如下幾個可疑的觸發條件:
出了問題確定要可以復現才更有利於解決問題,正所謂可以復現的 bug 就不叫 bug。復現問題以前,咱們經過分析 etcd 社區以前的相關 issue 發現,觸發該 bug 的共同條件都包含執行過 compaction 和 defrag 操做,同時重啓過 etcd 節點。所以,咱們計劃首先嚐試同時模擬這幾個操做,觀察是否可以在新的環境中復現。爲此咱們新建了一個集羣,而後經過編寫腳本向集羣中不停的寫入和刪除數據,直到 dbsize 達到必定程度後,對節點依次進行配置更新和重啓,並觸發 compaction 和 defrag 操做。然而通過屢次嘗試,咱們並無復現出相似於上述數據不一致的場景。
抽絲剝繭,初現端倪
緊接着,在以後的測試中無心發現,client 指定不一樣的 endpoint 寫數據,可以查到數據的節點也不一樣。好比,endpoint 指定爲 node1 進行寫數據,3個節點均可以查到數據;endpoint 指定爲 node2 進行寫數據,node2 和 node3 能夠查到;endpoint 指定爲 node3 寫數據,只有 node3 本身可以查到。具體狀況以下表:
因而咱們作出了初步的猜想,有如下幾種可能:
爲了驗證咱們的猜想,咱們進行了一系列測試來縮小問題範圍:
首先,咱們經過 endpoint status 查看集羣信息,發現 3 個節點的 clusterId,leader,raftTerm,raftIndex 信息均一致,而 dbSize 大小和 revision 信息不一致。clusterId 和 leader 一致,基本排除了集羣分裂的猜想,而 raftTerm 和 raftIndex 一致,說明 leader 是有向 follower 同步消息的,也進一步排除了第一個猜想,可是 WAL落盤有沒有異常還不肯定。dbSize 和 revision 不一致則進一步說明了 3 個節點數據已經發生不一致了。
其次,因爲 etcd 自己提供了一些 dump 工具,例如 etcd-dump-log 和 etcd-dump-db。咱們能夠像下圖同樣,使用 etcd-dump-log dump 出指定 WAL 文件的內容,使用 etcd-dump-db dump 出 db 文件的數據,方便對 WAL 和 db 數據進行分析。
因而,咱們向 node3 寫了一條便於區分的數據,而後經過 etcd-dump-log 來分析 3 個節點的 WAL,按照剛纔的測試,endpoint 指定爲 node3 寫入的數據,經過其餘兩個節點應該查不到的。可是咱們發現 3 個節點都收到了 WAL log,也就是說 WAL 並無丟,所以排除了第二個猜想。
接下來咱們 dump 了 db 的數據進行分析,發現 endpoint 指定爲 node3 寫入的數據,在其餘兩個節點的 db 文件裏找不到,也就是說數據確實沒有落到 db,而不是寫進去了查不出來。
既然 WAL 裏有而 db 裏沒有,所以很大多是 apply 流程異常了,數據可能在 apply 時被丟棄了。
因爲現有日誌沒法提供更有效的信息,咱們打算在 etcd 裏新加一些日誌來更好地幫助咱們定位問題。etcd 在作 apply 操做時,trace 日誌會打印超過每一個超過 100ms 的請求,咱們首先把 100ms 這個閾值調低,調整到 1ns,這樣每一個 apply 的請求都可以記錄下來,能夠更好的幫助咱們定位問題。
編譯好新版本以後,咱們替換了其中一個 etcd 節點,而後向不一樣 node 發起寫請求測試。果真,咱們發現了一條不一樣尋常的錯誤日誌:"error":"auth:revision in header is old",所以咱們判定問題極可能是由於——發出這條錯誤日誌的節點,對應的 key 恰好沒有寫進去。
搜索代碼後,咱們發現 etcd 在進行 apply 操做時,若是開啓了鑑權,在鑑權時會判斷 raft 請求 header 中的 AuthRevision,若是請求中的 AuthRevision 小於當前 node 的AuthRevision,則會認爲 AuthRevision 太老而致使 Apply 失敗。
func (as *authStore) isOpPermitted(userName string, revision uint64, key, rangeEnd []byte, permTyp authpb.Permission_Type) error { // ... if revision < as.Revision() { return ErrAuthOldRevision } // ...}
這樣看來,極可能是不一樣節點之間的 AuthRevision 不一致了,AuthRevision 是 etcd 啓動時直接從 db 讀取的,每次變動後也會及時的寫入 db,因而咱們簡單修改了下 etcd-dump-db工具,將每一個節點 db 內存儲的 AuthRevision 解碼出來對比了下,發現 3 個節點的 AuthRevision 確實不一致,node1 的 AuthRevision 最高,node3 的 AuthRevision 最低,這正好可以解釋以前的現象,endpoint 指定爲 node1 寫入的數據,3 個節點都能查到,指定爲 node3 寫入的數據,只有 node3 可以查到,由於 AuthRevision 較低的節點發起的 Raft 請求,會被 AuthRevision 較高的節點在 Apply 的過程當中丟棄掉(以下表)。
源碼以前,了無祕密?
目前爲止咱們已經能夠明確,新寫入的數據經過訪問某些 endpoint 查不出來的緣由是因爲 AuthRevision 不一致。可是,數據最開始發生不一致問題是不是由 AuthRevision 形成,還暫時不能判定。爲何這麼說呢?由於 AuthRevision 極可能也是受害者,好比 AuthRevision 和數據的不一致都是由同一個緣由致使的,只不過是 AuthRevision 的不一致放大了數據不一致的問題。可是,爲更進一步接近真相,咱們先假設 AuthRevision 就是致使數據不一致的罪魁禍首,進而找出致使 AuthRevision 不一致的真實緣由。
緣由到底如何去找呢?正所謂,源碼以前了無祕密,咱們首先想到了分析代碼。因而,咱們走讀了一遍 Auth 操做相關的代碼(以下),發現只有在進行權限相關的寫操做(如增刪用戶/角色,爲角色受權等操做)時,AuthRevision 纔會增長。AuthRevision 增長後,會和寫權限操做一塊兒,寫入 backend 緩存,當寫操做超過必定閾值(默認 10000 條記錄)或者每隔100ms(默認值),會執行刷盤操做寫入 db。因爲 AuthRevision 的持久化和建立用戶等操做的持久化放在一個事務內,所以基本不會存在建立用戶成功了,而 AuthRevision 沒有正常增長的狀況。
func (as *authStore) UserAdd(r *pb.AuthUserAddRequest) (*pb.AuthUserAddResponse, error) { // ... tx := as.be.BatchTx() tx.Lock() defer tx.Unlock() // Unlock時知足條件會觸發commit操做 // ... putUser(tx, newUser) as.commitRevision(tx) return &pb.AuthUserAddResponse{}, nil}func (t *batchTxBuffered) Unlock() { if t.pending != 0 { t.backend.readTx.Lock() // blocks txReadBuffer for writing. t.buf.writeback(&t.backend.readTx.buf) t.backend.readTx.Unlock() if t.pending >= t.backend.batchLimit { t.commit(false) } } t.batchTx.Unlock()}
那麼,既然 3 個節點的 AuthRevision 不一致,會不會是由於某些節點寫權限相關的操做丟失了,從而沒有寫入 db ?若是該猜想成立,3 個節點的 db 裏 authUser 和 authRole 的 bucket 內容應該有所不一樣纔對。因而爲進一步驗證,咱們繼續修改了下 etcd-dump-db 這個工具,加入了對比不一樣 db 文件 bucket 內容的功能。遺憾的是,經過對比發現,3 個節點之間的 authUser 和 authRole bucket 的內容並無什麼不一樣。
既然節點寫權限相關的操做沒有丟,那會不會是命令重複執行了呢?查看異常時間段內日誌時發現,其中包含了較多的 auth 操做;進一步分別比對 3 個節點的 auth 操做相關的日誌又發現,部分節點日誌較多,而部分節點日誌較少,看起來像是存在命令重複執行現象。因爲日誌壓縮,雖然暫時還不能肯定是重複執行仍是操做丟失,可是這些信息可以爲咱們後續的排查帶來很大啓發。
咱們繼續觀察發現,不一樣節點之間的 AuthRevison雖有差別,可是差別較小,並且差別值在咱們壓測期間沒有變過。既然不一樣節點之間的 AuthRevision 差別值沒有進一步放大,那麼經過新增的日誌基本上也看不出什麼問題,由於不一致現象的出現極可能是在過去的某個時間點瞬時形成的。這就形成咱們若是想要發現問題根因,仍是要可以復現 AuthRevison 不一致或者數據不一致問題才行,而且要可以抓到復現瞬間的現場。
問題彷佛又回到了原點,但好在咱們目前已經排除了不少干擾信息,將目標聚焦在了 auth 操做上。
混沌工程,成功復現
鑑於以前屢次手動模擬各類場景都沒能成功復現,咱們打算搞一套自動化的壓測方案來複現這個問題,方案制定時主要考慮的點有如下幾個:
如何增大復現的機率?
根據以前的排查結果,頗有多是 auth 操做致使的數據不一致,所以咱們實現了一個 monkey 腳本,每隔一段時間,會向集羣寫入隨機的用戶、角色,並向角色受權,同時進行寫數據操做,以及隨機的重啓集羣中的節點,詳細記錄每次一操做的時間點和執行日誌。
怎樣保證在復現的狀況下,可以儘量的定位到問題的根因?
根據以前的分析得出,問題根因大機率是 apply 過程當中出了問題,因而咱們在 apply 的流程里加入了詳細的日誌,並打印了每次 apply 操做committedIndex、appliedIndex、consistentIndex 等信息。
若是復現成功,如何可以在第一時間發現?
因爲日誌量太大,只有第一時間發現問題,纔可以更精確的縮小問題範圍,才能更利於咱們定位問題。因而咱們實現了一個簡單的 metric-server,每隔一分鐘拉取各個節點的 key 數量,並進行對比,將差別值暴露爲 metric,經過 prometheus 進行拉取,並用 grafana 進行展現,一旦差別值超過必定閾值(寫入數據量大的狀況下,就算併發統計各個節點的 key 數量,也可能會有少許的差別,因此這裏有一個容忍偏差),則馬上經過統一告警平臺向咱們推送告警,以便於及時發現。
方案搞好後,咱們新建了一套 etcd 集羣,部署了咱們的壓測方案,打算進行長期觀察。結果次日中午,咱們就收到了微信告警——集羣中存在數據不一致現象。
因而,咱們馬上登陸壓測機器進行分析,首先停掉了壓測腳本,而後查看了集羣中各個節點的 AuthRevision,發現 3 個節點的 AuthRevision 果真不同!根據 grafana 監控面板上的監控數據,咱們將數據不一致出現的時間範圍縮小到了 10 分鐘內,而後重點分析了下這 10 分鐘的日誌,發如今某個節點重啓後,consistentIndex 的值比重啓前要小。然而 etcd 的全部 apply 操做,冪等性都依賴 consistentIndex 來保證,當進行 apply 操做時,會判斷當前要 apply 的 Entry 的 Index 是否大於 consistentIndex,若是 Index 大於 consistentIndex,則會將 consistentIndex 設爲 Index,並容許該條記錄被 apply。不然,則認爲該請求被重複執行了,不會進行實際的 apply 操做。
// applyEntryNormal apples an EntryNormal type raftpb request to the EtcdServerfunc (s *EtcdServer) applyEntryNormal(e *raftpb.Entry) { shouldApplyV3 := false if e.Index > s.consistIndex.ConsistentIndex() { // set the consistent index of current executing entry s.consistIndex.setConsistentIndex(e.Index) shouldApplyV3 = true } // ... // do not re-apply applied entries. if !shouldApplyV3 { return } // ...}
也就是說,因爲 consistentIndex 的減少,etcd 自己依賴它的冪等操做將變得再也不冪等,致使權限相關的操做在 etcd 重啓後被重複 apply 了,即一共apply 了兩次!
爲什麼 consistentIndex 會減少?走讀了 consistentIndex 相關代碼後,咱們終於發現了問題的根因:consistentIndex 自己的持久化,依賴於 mvcc 的寫數據操做;經過 mvcc 寫入數據時,會調用 saveIndex 來持久化 consistentIndex 到 backend,而 auth 相關的操做,是直接讀寫的 backend,並無通過 mvcc。這就致使,若是作了權限相關的寫操做,而且以後沒有經過 mvcc 寫入數據,那麼這期間 consistentIndex 將不會被持久化,若是這時候重啓了 etcd,就會形成權限相關的寫操做被 apply 兩次,帶來的反作用可能會致使 AuthRevision 重複增長,從而直接形成不一樣節點的 AuthRevision 不一致,而 AuthRevision 不一致又會形成數據不一致。
func putUser(lg *zap.Logger, tx backend.BatchTx, user *authpb.User) { b, err := user.Marshal() tx.UnsafePut(authUsersBucketName, user.Name, b) // 直接寫入Backend,未通過MVCC,此時不會持久化consistentIndex}func (tw *storeTxnWrite) End() { // only update index if the txn modifies the mvcc state. if len(tw.changes) != 0 { tw.s.saveIndex(tw.tx) // 當經過MVCC寫數據時,會觸發consistentIndex持久化 tw.s.revMu.Lock() tw.s.currentRev++ } tw.tx.Unlock() if len(tw.changes) != 0 { tw.s.revMu.Unlock() } tw.s.mu.RUnlock()}
再回過頭來,爲何數據不一致了還能夠讀出來,並且讀出來的數據還可能不同?etcd 不是使用了 raft 算法嗎,難道不可以保證強一致性嗎?其實這和 etcd 自己的讀操做實現有關。
而影響 ReadIndex 操做的,一個是 leader 節點的 CommittedIndex,一個是當前節點的 AppliedIndex,etcd 在 apply 過程當中,不管 apply 是否成功,都會更新 AppliedIndex,這就形成,雖然當前節點 apply 失敗了,但讀操做在判斷的時候,並不會感知到這個失敗,從而致使某些節點可能讀不出來數據;並且 etcd 支持多版本併發控制,同一個 key 能夠存在多個版本的數據,apply 失敗可能只是更新某個版本的數據失敗,這就形成不一樣節點之間最新的數據版本不一致,致使讀出不同的數據。
該問題從 2016 年引入,全部開啓鑑權的 etcd3 集羣都會受到影響,在特定場景下,會致使 etcd 集羣多個節點之間的數據不一致,而且 etcd 對外表現還能夠正常讀寫,日誌無明顯報錯。
觸發條件
使用的爲 etcd3 集羣,而且開啓了鑑權。
etcd 集羣中節點發生重啓。
節點重啓以前,有 grant-permission 操做(或短期內對同一個權限操做連續屢次增刪),且操做以後重啓以前無其餘數據寫入。
瞭解了問題的根因,修復方案就比較明確了,咱們只須要在 auth 操做調用 commitRevision 後,觸發 consistentIndex 的持久化操做,就可以保證 etcd 在重啓的時候 consistentIndex 的自己的正確性,從而保證 auth 操做的冪等性。具體的修復方式咱們已經向 etcd 社區提交了 PR #11652,目前這個特性已經 backport 到 3.4,3.3 等版本,將會在最近一個 release 更新。
那麼若是數據已經不一致了怎麼辦,有辦法恢復嗎?在 etcd 進程沒有頻繁重啓的狀況下,能夠先找到 authRevision 最小的節點,它的數據應該是最全的,而後利用 etcd 的 move-leader 命令,將 leader 轉移到這個節點,再依次將其餘節點移出集羣,備份並刪除數據目錄,而後將節點從新加進來,此時它會從 leader 同步一份最新的數據,這樣就可使集羣其餘節點的數據都和 leader 保持一致,即最大可能地不丟數據。
須要注意的是,升級有風險,新版本雖然解決了這個問題,但因爲升級過程當中須要重啓 etcd,這個重啓過程仍可能觸發這個 bug。所以升級修復版本前建議中止寫權限相關操做,而且手動觸發一次寫數據操做以後再重啓節點,避免由於升級形成問題。
另外,不建議直接跨大版本升級,例如從 etcd3.2 → etcd3.3。大版本升級有必定的風險,需謹慎測試評估,咱們以前發現過由 lease 和 auth 引發的另外一個不一致問題,具體可見 issue #11689,以及相關 PR #11691。
致使該問題的直接緣由,是因爲 consistentIndex 在進行權限相關操做時未持久化,從而致使 auth 相關的操做不冪等,形成了數據的不一致。
而形成 auth 模塊未持久化 consistentIndex 的一個因素,是由於 consistentIndex 目前是在 mvcc 模塊實現的,並未對外暴露持久化接口,只能經過間接的方式來調用,很容易漏掉。爲了優化這個問題,咱們重構了 consistentIndex 相關操做,將它獨立爲一個單獨的模塊,其餘依賴它的模塊能夠直接調用,必定程度上能夠避免未來再出現相似問題,具體見 PR #11699。
另外一方面,etcd 的 apply 操做自己是個異步流程,並且失敗以後沒有打印任何錯誤日誌,很大程度上增長了排障的難度,所以咱們後邊也向社區提交了相關 PR #11670,來優化 apply 失敗時的日誌打印,便於定位問題。
形成問題定位困難的另外一個緣由,是 auth revision 目前沒有對外暴露 metric 或者 api,每次查詢只能經過 [etcd-dump-db 工具來直接從 db 獲取,爲方便 debug,咱們也增長了相關的
metric](https://github.com/etcd-io/etcd/pull/11652/commits/f14d2a087f7b0fd6f7980b95b5e0b945109c95f3) 和 status api,加強了 auth revision 的可觀測性和可測試性。
感謝在 PR 提交過程當中,etcd 社區 jingyih,mitake 的熱心幫助和建議!