Kubernetes 驚天地泣鬼神之大Bug

自從三月份生產、非生產全面上線 Kubernetes 後，本以為部署的問題可以舒一口氣了，但是斷斷續續在生產、非生產環境發現一個詭異的問題，這禮拜又調試了三天，在快要放棄的時候居然找到原因了，此缺陷影響目前(2018-5-23)為止所有 Kubernetes 版本(見後面更新，誇大了)，包括 Github 當前 master 分支，後果是某種情況觸發下，Kubernetes service 不能提供服務，影響非常惡劣。

問題的現象是，在某種情況下，一個或者多個 Kubernetes service 對應的 Kubernetes endpoints 消失幾分鐘至幾十分鐘，然後重新出現，然後又消失，用 "kubectl get ep --all-namespaces" 不斷查詢，可以觀察到一些 AGE 在分鐘級別的 endpoints 要麼忽然消失，要麼 AGE 突然變小從一分鐘左右起步。Endpoints 的不穩定，必然導致對應的 Kubernetes service 無法穩定提供服務。有人在 Github 上報告了 issue，但是一直沒得到開發人員注意和解決。

首先解釋下 Kubernetes 大體上的實現機制，有助於理解下面的破案過程。

Kubernetes 的實現原理跟配置管理工具 CFengine、Ansible、Salt 等非常類似：configuration convergence——不斷的比較期望的配置和實際的配置，修訂實際配置以收斂到期望配置。

Kubernetes 的關鍵系統服務有 api-server, scheduler, controller-manager 三個。api-server 一方面作為 Kubernetes 系統的訪問入口點，一方面作為背後 etcd 存儲的代理伺服器，Kubernetes 里的所有資源對象，包括 Service、Deployment、ReplicaSet、DaemonSet，Pod、Endpoint、ConfigMap、Secret 等等，都是通過 api-server 檢查格式後，以 protobuf 格式序列化並存入 etcd。這就是一個寫入「期望配置」的過程。

Controller-manager 服務里包含了很多 controller 實例，對應各種資源類型：

這些 controller 做的事情就是收斂：它通過 api-server 的 watch API 去間接的 watch etcd，以收取 etcd 里數據的 changelog，對改變(包括ADD,DELETE,UPDATE)的資源（也就是期望的「配置「），逐個與通過 kubelet + docker 收集到的信息（實際「配置」）做對比並修正差異。

比如 etcd 里增加了一個 Pod 資源，那麼 controller 就要請求 scheduler 調度，然後請求 kubelet 創建 Pod，如果etcd里刪除了一個 Service 資源，那麼就要刪除其對應的 endpoint 資源，而這個 endpoint 刪除操作會被 kube-proxy 監聽到而觸發實際的 iptables 命令。

注意上面 controller 通過 watch 獲取 changelog 只是一個實現上的優化，它沒有周期性的拿出所有的資源對象然後逐個判斷，在集群規模很大時，這樣的全量收斂是很慢的，後果就是集群的調度、自我修復進行的非常慢。

有了大框架的理解後，endpoints 被誤刪的地方是很容易找到的：

然後問題來了，什麼情況下那個 Services(namespace).Get(name) 會返回錯誤呢？通過注釋，可以看到在 service 刪除時會走到 397 行里去，把無用的 endpoints 刪掉，因為 endpoint 是給 service 服務的，service 不存在時，endpoint 沒有存在的意義。

然後問題來了，通過 "kubectl get svc" 可以看到出問題期間，服務資源一直都在，並沒有重建，也沒有剛剛部署，甚至很多服務資源都是創建了幾個月，為啥它對應的 endpoints 會被誤刪然後重建呢？這個問題困擾了我兩個月，花了很長時間和很多腦細胞，今天在快放棄時突然有了重大發現。

由於我司搭建的 Kubernetes 集群開啟了 X509 認證以及 RBAC 許可權控制，為了便於審查，我開啟了 kube-apiserver 的審計日誌，在出問題時，審計日誌中有個特別的模式：

審計日誌中，在每個 endpoint delete & create 發生前，都有一個 "/api/v1/services...watch=true" 的 watch 調用，上面講到，controller-manager 要不斷的去爬 etcd 裡面資源的 changelog，這裡很奇怪的問題是，這個調用的 "resourceVersion=xxx" 的版本值始終不變，難道不應該不斷從 changelog 末尾繼續爬取因為 resourceVersion 不斷遞增么？

通過一番艱苦卓絕的連猜帶蒙，終於找到「爬取changelog」對應的代碼：

上面的代碼對 resourceVersion 的處理邏輯是： 遍歷 event 列表，取當前 event 的 "resourceVersion" 欄位作為新的要爬取的「起始resourceVersion"，所以很顯然遍歷結束後，"起始resourceVersion" 也就是最後一條 event 的 "resourceVersion"。

好了，我們來看看 event 列表漲啥樣，把上面 api-server 的請求照搬就可以看到了：

kubectl proxycurl -s localhost:8001/api/v1/services?resourceVersion=xxxx&timeoutSeconds=yyy&watch=true

可以很明顯看到，坑爹，resourceVersion 不是遞增的！

這個非遞增的問題其實很容易想明白，resourceVersion 並不是 event 的序列號，它是 Kubernetes 資源自身的版本號，如果把 etcd 看作 Subversion，兩者都有一個全局遞增的版本號，把 Kubernetes 資源看作 Subversion 里保存的文件。 在 svn revision=100 時存入一個文件 A，那麼A的版本是 100，然後不斷提交其它文件的修改到 svn，然後在某個版本刪掉 A，此時用 svn log 看到的相關文件的「自身最後一次修改版本」並不是遞增的，最後一條的「自身最後一次修改版本」是 100.

所以真相大白了，reflector.go 那段遍歷 etcd "changelog" 的代碼，誤以為 event 序列的 resourceVersion 是遞增的了，雖然絕大部分時候是這樣的。由於這段代碼是通用的，所有資源都受這個影響，所以是非常嚴重的 bug，之前看到很多人報告（我自己也遇到）controller-manager 報錯 "reflector.go:341] k8s.io/kubernetes/pkg/controller/bootstrap/bootstrapsigner.go:152: watch of *v1.ConfigMap ended with: too old resource version: " 很可能也是這個導致的，因為它失誤從很老的 resourceVersion 開始爬取 etcd "changelog"，但 etcd 已經把太老的 changelog 給 「compact」 掉了。

最後總結下怎麼觸發以及繞過這個 bug：

• 觸發

陸續創建、刪除、創建 Kubernetes service 對象，然後"kubectl delete svc xxx"刪掉創建時間靠前的 service，也就是往 service event list 末尾插入了一條 resourceVersion 比較小的記錄，這將使得 controller-manager 去從已經爬過的 service event list 位置重新爬取重放，然後就重放了 service 的 ADDED、DELETED event，於是 controller-manager 內存里緩存的 service 對象被刪除，導致 EndpointController 刪除了「不存在的」service 對應的 endpoints。

• 繞過
• 用 docker restart 重啟 kube-controller-manager 容器，強迫其從 event list 最新位置開始爬取
• 創建一個 service，其 resourceVersion 會是 etcd 的最新全局版本號，這個 ADDED event 會出現在 event list 末尾，從而 controller-manager 從這個最新的 resourceVersion 開始爬取
• "kubectl edit" 修改某個 service，加點無意義的 label 之類的，保存，這樣其 resourceVersion 也會更新，之後跟上一個 workaround 原理一樣了。
• 錯誤的繞過方式
• "kubectl delete pod/xxx"：不影響 service event list
• "kubectl delete deploy/xxxx": 不影響 service event list

Kubernetes 里凡是創建後基本不變的資源，比如 service、configmap、secrets 都會受這個影響，它們的版本號都很久，刪一個後都會觸發這個 bug，比如 configmap，可能就會被重複的更新，映射到容器里的 config file 也就不斷更新，對於不支持 config hot reload 的服務沒有影響，對於支持 config hot reload 的服務，會頻繁的重新載入配置文件重新初始化，可能導致意想不到的問題。

Bug 的修復很簡單，在遍歷 event list 選擇 resourceVersion 時，總是取 max(event.resourceVersion, currentResourceVersion) 即可，我提了個 pull request 給 Kubernetes 官方看看，希望我這個粗暴的修正不會帶來新的問題??

【更新】：avoid wrongly replaying old events in kube-controller-manager by Dieken · Pull Request #64209 · kubernetes/kubernetes 官方開發同學很快指出這個問題已經修正了，就在 1.9.3，我正好用的 1.9.2，看了下 1.9.3 的更新說明，他媽的輕描淡寫啊！

Fixes an issue where the resourceVersion of an object in a DELETE watch

event was not the resourceVersion of the delete itself, but of the last

update to the object. This could disrupt the ability of clients clients

to re-establish watches properly. (#58547, @liggitt)

按 liggitt 的說法，升級到這些版本就好了：v1.8.8+, v1.9.3+, and v1.10.0+