antony@notes:~/kubernetes$ cat "K3s-系統性崩潰分析報告.md"

K3s 系統性崩潰分析報告

2025-05-13· kubernetes

K3s 系統性崩潰分析報告

K3s log 分析

etcd 要將資料寫入磁碟時超過 46 秒 (一般應在數毫秒～1 秒內完成)

{
  "level": "warn",
  "ts": "2025-05-11T00:22:46.781+0800",
  "caller": "wal/wal.go:808",
  "msg": "slow fdatasync",
  "took": "46.889101479s",
  "expected-duration": "1s"
}

etcd 處理一個單純 Read 請求耗時 45.89 秒，遠遠超出預期的 100 毫秒，而且最終還是失敗了（context deadline exceeded）。

{
  "level": "warn",
  "ts": "2025-05-11T00:22:46.791+0800",
  "caller": "etcdserver/util.go:163",
  "msg": "apply request took too long",
  "took": "45.8901115s",
  "expected-duration": "100ms",
  "prefix": "read-only range ",
  "request": "key:\"/registry/mutatingwebhookconfigurations/vault-agent-injector-cfg\" ",
  "response": "",
  "error": "context deadline exceeded"
}

etcd 為了完成高一致性讀取（linearized read），花了 45.89 秒等待 raft 演算法取得共識

{
  "level": "info",
  "ts": "2025-05-11T00:22:46.791+0800",
  "caller": "traceutil/trace.go:145",
  "msg": "trace[381326135] range",
  "detail": "{range_begin:/registry/mutatingwebhookconfigurations/vault-agent-injector-cfg; range_end:; }",
  "duration": "45.890191566s",
  "start": "2025-05-11T00:22:00.901+0800",
  "end": "2025-05-11T00:22:46.791+0800",
  "steps": [
    "trace[381326135] agreement among raft nodes before linearized reading  (duration: 45.890156006s)"
  ]
}

檢查本地 etcd 執行狀態失敗，因為檢查超過最大等候時間，仍未完成回應

{
  "time": "2025-05-11T00:22:46.791838023+08:00",
  "level": "error",
  "msg": "Failed to check local etcd status for learner management: context deadline exceeded"
}

K3s 再次嘗試從 etcd 讀取 PVC（PersistentVolumeClaim）資源時，為了保證讀取一致性（linearized read），觸發了 etcd 的 Raft 共識程序。不幸的是，這個操作被卡住了整整 46.9 秒（遠超出預期的 100 毫秒），最終因逾時（request timed out）失敗。

[
  {
    "log_time": "May 11 00:22:48",
    "host": "fetci",
    "process": "k3s",
    "pid": 1321,
    "entry": {
      "level": "warn",
      "ts": "2025-05-11T00:22:46.808+0800",
      "caller": "etcdserver/util.go:163",
      "msg": "apply request took too long",
      "took": "46.914240959s",
      "expected-duration": "100ms",
      "prefix": "read-only range ",
      "request": "key:\"/registry/persistentvolumeclaims/minio/data-2-minio-1\" ",
      "response": "",
      "error": "etcdserver: request timed out"
    }
  },
  {
    "log_time": "May 11 00:22:48",
    "host": "fetci",
    "process": "k3s",
    "pid": 1321,
    "entry": {
      "level": "info",
      "ts": "2025-05-11T00:22:46.808+0800",
      "caller": "traceutil/trace.go:145",
      "msg": "trace[656268623] range",
      "detail": "{range_begin:/registry/persistentvolumeclaims/minio/data-2-minio-1; range_end:; }",
      "duration": "46.914291657s",
      "start": "2025-05-11T00:21:59.894+0800",
      "end": "2025-05-11T00:22:46.808+0800",
      "steps": [
        "trace[656268623] 'agreement among raft nodes before linearized reading'  (duration: 46.914239825s)"
      ]
    }
  }
]

K3s 在 2025-05-11 00:22:46 時，因 etcd 效能嚴重惡化，導致 Kubernetes 內部的 leader election 無法維持，當前節點放棄領導地位（stopped leading）。隨後，關鍵元件（如 HPA、PVC、DaemonSet、Volume 管理等 controller）陸續進入 shutdown，Kubelet 因 container runtime 不可用而停止同步 Pod，API server 請求大量 timeout，整個 control plane 逐步失能。這是一場由 etcd timeout 引發的 control plane node 系統性崩潰。

May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.308855    1321 horizontal.go:215] horizontal pod autoscaler controller worker shutting down
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.365686    1321 event.go:291] "Event occurred" object="" kind="Lease" apiVersion="coordination.k8s.io/v1" type="Normal" reason="LeaderElection" message="fetci_29748a93-d583-4cd5-bb55-a9c43db0a7ab stopped leading"
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.365719    1321 pvc_protection_controller.go:122] "Shutting down PVC protection controller"
May 11 00:22:48 fetci k3s[1321]: E0511 00:22:46.423085    1321 leaderelection.go:325] error retrieving resource lock kube-system/cloud-controller-manager: Get "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/cloud-controller-manager?timeout=5s": context deadline exceeded
May 11 00:22:48 fetci k3s[1321]: E0511 00:22:46.423232    1321 kubelet.go:1870] "Skipping pod synchronization" err="container runtime is down"
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.480179    1321 pv_controller_base.go:461] volume worker queue shutting down
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.480226    1321 daemon_controller.go:299] Shutting down daemon sets controller
May 11 00:22:48 fetci k3s[1321]: E0511 00:22:46.480295    1321 wrap.go:54] timeout or abort while handling: GET "/apis/coordination.k8s.io/v1/namespaces/tigera-operator/leases/operator-lock"
May 11 00:22:48 fetci k3s[1321]: E0511 00:22:46.480634    1321 status.go:71] apiserver received an error that is not an metav1.Status: context.deadlineExceededError{}: context deadline exceeded
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.480859    1321 endpointslicemirroring_controller.go:224] Shutting down EndpointSliceMirroring controller
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.481235    1321 pv_protection_controller.go:95] Shutting down PV protection controller
May 11 00:22:48 fetci k3s[1321]: I0511 00:22:46.768134    1321 trace.go:205] Trace[1208467430]: "GuaranteedUpdate etcd3" type:*coordination.Lease (11-May-2025 00:22:06.292) (total time: 40475ms):
May 11 00:22:48 fetci k3s[1321]: Trace[1208467430]: [40.475369945s] [40.475369945s] END

systemd 偵測到 K3s 無法繼續正常運作，觸發服務重啟機制。

May 11 00:22:53 fetci systemd[1]: k3s.service: Service hold-off time over, scheduling restart.
May 11 00:22:53 fetci systemd[1]: k3s.service: Scheduled restart job, restart counter is at 1.
May 11 00:22:53 fetci systemd[1]: Stopped Lightweight Kubernetes.

原始 log 資訊

May 11 00:22:48 rancher k3s[1321]: {"level":"warn","ts":"2025-05-11T00:22:46.781+0800","caller":"wal/wal.go:808","msg":"slow fdatasync","took":"46.889101479s","expected-duration":"1s"}
May 11 00:22:48 rancher k3s[1321]: {"level":"warn","ts":"2025-05-11T00:22:46.782+0800","caller":"etcdserver/server.go:1079","msg":"failed to revoke lease","lease-id":"51ab96b8f865613c","error":"etcdserver: request timed out"}
May 11 00:22:48 rancher k3s[1321]: time="2025-05-11T00:22:46.788366607+08:00" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"
May 11 00:22:48 rancher k3s[1321]: {"level":"warn","ts":"2025-05-11T00:22:46.791+0800","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"45.8901115s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/mutatingwebhookconfigurations/vault-agent-injector-cfg\" ","response":"","error":"context deadline exceeded"}
May 11 00:22:48 rancher k3s[1321]: {"level":"info","ts":"2025-05-11T00:22:46.791+0800","caller":"traceutil/trace.go:145","msg":"trace[381326135] range","detail":"{range_begin:/registry/mutatingwebhookconfigurations/vault-agent-injector-cfg; range_end:; }","duration":"45.890191566s","start":"2025-05-11T00:22:00.901+0800","end":"2025-05-11T00:22:46.791+0800","steps":["trace[381326135] 'agreement among raft nodes before linearized reading'  (duration: 45.890156006s)"]}
May 11 00:22:48 rancher k3s[1321]: {"level":"warn","ts":"2025-05-11T00:22:46.791+0800","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://127.0.0.1:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
May 11 00:22:48 rancher k3s[1321]: time="2025-05-11T00:22:46.791838023+08:00" level=error msg="Failed to check local etcd status for learner management: context deadline exceeded"
May 11 00:22:48 rancher k3s[1321]: {"level":"warn","ts":"2025-05-11T00:22:46.808+0800","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"46.914240959s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/persistentvolumeclaims/minio/data-2-minio-1\" ","response":"","error":"etcdserver: request timed out"}
May 11 00:22:48 rancher k3s[1321]: {"level":"info","ts":"2025-05-11T00:22:46.808+0800","caller":"traceutil/trace.go:145","msg":"trace[656268623] range","detail":"{range_begin:/registry/persistentvolumeclaims/minio/data-2-minio-1; range_end:; }","duration":"46.914291657s","start":"2025-05-11T00:21:59.894+0800","end":"2025-05-11T00:22:46.808+0800","steps":["trace[656268623] 'agreement among raft nodes before linearized reading'  (duration: 46.914239825s)"]}
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.308855    1321 horizontal.go:215] horizontal pod autoscaler controller worker shutting down
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.365686    1321 event.go:291] "Event occurred" object="" kind="Lease" apiVersion="coordination.k8s.io/v1" type="Normal" reason="LeaderElection" message="rancher_29748a93-d583-4cd5-bb55-a9c43db0a7ab stopped leading"
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.365719    1321 pvc_protection_controller.go:122] "Shutting down PVC protection controller"
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.423085    1321 leaderelection.go:325] error retrieving resource lock kube-system/cloud-controller-manager: Get "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/cloud-controller-manager?timeout=5s": context deadline exceeded
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.423232    1321 kubelet.go:1870] "Skipping pod synchronization" err="container runtime is down"
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.480179    1321 pv_controller_base.go:461] volume worker queue shutting down
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.480226    1321 daemon_controller.go:299] Shutting down daemon sets controller
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.480295    1321 wrap.go:54] timeout or abort while handling: GET "/apis/coordination.k8s.io/v1/namespaces/tigera-operator/leases/operator-lock"
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.480634    1321 status.go:71] apiserver received an error that is not an metav1.Status: context.deadlineExceededError{}: context deadline exceeded
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.480859    1321 endpointslicemirroring_controller.go:224] Shutting down EndpointSliceMirroring controller
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.481235    1321 pv_protection_controller.go:95] Shutting down PV protection controller
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.768134    1321 trace.go:205] Trace[1208467430]: "GuaranteedUpdate etcd3" type:*coordination.Lease (11-May-2025 00:22:06.292) (total time: 40475ms):
May 11 00:22:48 rancher k3s[1321]: Trace[1208467430]: [40.475369945s] [40.475369945s] END
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.779070    1321 authentication.go:63] "Unable to authenticate the request" err="[invalid bearer token, context canceled]"
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.791360    1321 trace.go:205] Trace[800629099]: "GuaranteedUpdate etcd3" type:*admissionregistration.MutatingWebhookConfiguration (11-May-2025 00:22:00.896) (total time: 45894ms):
May 11 00:22:48 rancher k3s[1321]: Trace[800629099]: [45.894632804s] [45.894632804s] END
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.792371    1321 trace.go:205] Trace[1819075853]: "Patch" url:/apis/admissionregistration.k8s.io/v1beta1/mutatingwebhookconfigurations/vault-agent-injector-cfg,user-agent:vault-k8s/v0.0.0 (linux/amd64) kubernetes/$Format,client:172.99.56.6,accept:application/json, */*,protocol:HTTP/1.1 (11-May-2025 00:22:00.896) (total time: 45895ms):
May 11 00:22:48 rancher k3s[1321]: Trace[1819075853]: [45.895797558s] [45.895797558s] END
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.792578    1321 trace.go:205] Trace[1934991911]: "Create" url:/api/v1/namespaces/default/events,user-agent:k3s/v1.21.11+k3s1 (linux/amd64) kubernetes/4eb3a48/kube-controller-manager,client:127.0.0.1,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (11-May-2025 00:22:08.573) (total time: 38218ms):
May 11 00:22:48 rancher k3s[1321]: Trace[1934991911]: [38.218578079s] [38.218578079s] END
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.797679    1321 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}: context canceled
May 11 00:22:48 rancher k3s[1321]: I0511 00:22:46.799129    1321 trace.go:205] Trace[1793283042]: "GuaranteedUpdate etcd3" type:*core.Endpoints (11-May-2025 00:22:05.680) (total time: 41118ms):
May 11 00:22:48 rancher k3s[1321]: Trace[1793283042]: [41.118330989s] [41.118330989s] END
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.808172    1321 writers.go:117] apiserver was unable to write a JSON response: http: Handler timeout
May 11 00:22:48 rancher k3s[1321]: E0511 00:22:46.815927    1321 server.go:273] "Unable to authenticate the request due to an error" err="context canceled"
May 11 00:22:53 rancher systemd[1]: k3s.service: Service hold-off time over, scheduling restart.
May 11 00:22:53 rancher systemd[1]: k3s.service: Scheduled restart job, restart counter is at 1.
May 11 00:22:53 rancher
systemd[1]: Stopped Lightweight Kubernetes.

Run Kube-vip as Cloud Provider on HA K3s 實測 API Server 會 cache K8s metadata