k8s (20.04) 연구노트 - involuntary disruption

k8s (20.04) 연구노트 - involuntary disruption

---

서버 Down 시 Pod를 언제 recover 하는가?

아래 글에서 기본적인 내용을 참고했다.

• https://medium.com/tailwinds-navigator/kubernetes-tip-how-to-make-kubernetes-react-faster-when-nodes-fail-1e248e184890

설정 (api-server)

    - --default-not-ready-toleration-seconds=30
    - --default-unreachable-toleration-seconds=30
    - --v=6

설정 (controller-manager)

    - --node-monitor-grace-period=30s
    - --node-monitor-period=10s
    - --v=6

서버 Down 발생 (Host 서버에서 측정 Guest와 초가 정확하지 않을 수 있음)

• 시점 : 05:50:12

2021-02-19 05:50:12.509+0000: shutting down, reason=destroyed

마지막 node 상태 캐치 (해당 상태 점검은 10초마다.)

• 시점 : 05:50:18

{"log":"I0219 05:50:18.806119       1 node_lifecycle_controller.go:1076] Node ha01-worker-3 ReadyCondition updated. Updating timestamp: \u0026NodeStatus{Capacity:ResourceList{cpu: {{8 0} {\u003cnil\u003e} 8 DecimalSI},ephemeral-storage: {{25463283712 0} {\u003cnil\u003e}  BinarySI},hugepages-2Mi: {{0 0} {\u003cnil\u003e} 0 DecimalSI},memory: {{16643895296 0} {\u003cnil\u003e} 16253804Ki BinarySI},pods: {{110 0} {\u003cnil\u003e} 110 DecimalSI},},Allocatab

30초 동안 not ready 여서 status 변경됨 (10초 후 status 변경함)

• 시점: 05:50:18

{"log":"I0219 05:50:48.812481       1 node_lifecycle_controller.go:1123] node ha01-worker-3 hasn't been updated for 30.006107725s. Last Ready is: \u0026NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2021-02-19 05:50:09 +0000 UTC,LastTransitionTime:2021-02-19 05:47:04 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,}\n","stream":"stderr","time":"2021-02-19T05:50:48.81288637Z"}

...

{"log":"I0219 05:50:48.842309       1 event.go:291] \"Event occurred\" object=\"ha01-worker-3\" kind=\"Node\" apiVersion=\"v1\" type=\"Normal\" reason=\"NodeNotReady\" message=\"Node ha01-worker-3 status is now: NodeNotReady\"\n","stream":"stderr","time":"2021-02-19T05:50:48.842928831Z"}

여기서 default-not-ready-toleration-seconds 시점이 마지막 node 상태 캐치 이후 30인지 not ready로 변경된 이후 30초 인지 확인할 필요가 있어 추가로 테스트를 진행했다.

Ping에 timestamp를 걸어서 언제 Network 요청이 끊기는지 정확히 확인해보자

ping 10.98.90.22 | while read pong; do echo "$(date): $pong"; done

아래와 같이 현재 worker-3에 httpd pod 한개가 수행중이고 Cluster가 당황(?) 하도록 Node를 Host에서 destroy 할 것이다.

[root@ha01-master-1 manifests]# kubectl get pod -o wide |grep worker-3
httpd-57fc687dcc-hmz6w       1/1     Running   0          103s    10.233.77.199    ha01-worker-3   <none>           <none>

우선 Fact 기준으로 시간차순 사건을 나열하자.

VM 중지 ( 06:29:21 )

2021-02-19 06:29:21.276+0000: shutting down, reason=destroyed

Ping 응답 없음 (06:29:20 까지 응답이 있으니 06:29:21 위와 동일)

Fri Feb 19 06:29:20 UTC 2021: 64 bytes from 10.98.90.22: icmp_seq=121 ttl=64 time=0.642 ms
Fri Feb 19 06:29:47 UTC 2021: From 10.98.90.10 icmp_seq=144 Destination Host Unreachable

controller-manager Log에서 보면 (06:29:19에 마지막 체크가 된 것을 볼 수 있다.)

{"log":"I0219 06:29:19.573699       1 node_lifecycle_controller.go:1076] Node ha01-worker-3 ReadyCondition updated. Updating timestamp: \u0026NodeStatus{Capacity:ResourceList{cpu: {{8 0} {\u003cnil\u003e} 8 DecimalSI},ephemeral-storage: ...

즉 node-monitor-grace-period 설정에 따르면 (06:29:49) 에 Node가 NotReady로 바뀌어야한다.

예상과 맞게 아래와 같이 마지막 체크 이후 30초 지난 시간에 Node를 NotReady로 변경했다. (로그가 상당히 보기 어렵다.)

{"log":"I0219 06:29:49.582156       1 node_lifecycle_controller.go:1123] node ha01-worker-3 hasn't been updated for 30.007708003s. Last Ready is: \u0026NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2021-02-19 06:29:14 +0000 UTC,LastTransitionTime:2021-02-19 06:23:11 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,}\n","stream":"stderr","time":"2021-02-19T06:29:49.582451405Z"}

...

{"log":"I0219 06:29:49.628030       1 event.go:291] \"Event occurred\" object=\"ha01-worker-3\" kind=\"Node\" apiVersion=\"v1\" type=\"Normal\" reason=\"NodeNotReady\" message=\"Node ha01-worker-3 status is now: NodeNotReady\"\n","stream":"stderr","time":"2021-02-19T06:29:49.628183932Z"}

이제 위 pod가 언제 migration 되는지 시점을 살펴보자

우선 (06:29:49) 동일한 시점에 pod의 ready status를 false로 변경했다.

{"log":"I0219 06:29:49.767748       1 controller_utils.go:140] Updating ready status of pod httpd-57fc687dcc-hmz6w to false\n","stream":"stderr","time":"2021-02-19T06:29:49.767927237Z"}

그리고 pod의 ready status가 false로 바뀐 30초가 아닌 40초에 deployment에서 pod를 delete하기 시작했다.

(06:30:29)

{"log":"I0219 06:30:29.941856       1 deployment_controller.go:570] Started syncing deployment \"default/httpd\" (2021-02-19 06:30:29.941808681 +0000 UTC m=+2589.990333166)\n","stream":"stderr","time":"2021-02-19T06:30:29.942115501Z"}

{"log":"I0219 06:30:29.942377       1 progress.go:191] Queueing up deployment \"httpd\" for a progress check now\n","stream":"stderr","time":"2021-02-19T06:30:29.942558578Z"}

{"log":"I0219 06:30:29.942437       1 deployment_controller.go:572] Finished syncing deployment \"default/httpd\" (619.337µs)\n","stream":"stderr","time":"2021-02-19T06:30:29.942584741Z"}

{"log":"I0219 06:30:30.017437       1 taint_manager.go:106] NoExecuteTaintManager is deleting Pod: default/httpd-57fc687dcc-hmz6w\n","stream":"stderr","time":"2021-02-19T06:30:30.017600845Z"}

{"log":"I0219 06:30:30.017853       1 event.go:291] \"Event occurred\" object=\"default/httpd-57fc687dcc-hmz6w\" kind=\"Pod\" apiVersion=\"\" type=\"Normal\" reason=\"TaintManagerEviction\" message=\"Marking for deletion Pod default/httpd-57fc687dcc-hmz6w\"\n","stream":"stderr","time":"2021-02-19T06:30:30.018477948Z"}

우선 pod ready 상태 이후 default-not-ready-toleration-seconds 에 의해 pod가 이관됨을 볼 수 있다.

현재 설정은 30초 이지만 Default는 300초 즉 5분이기 때문에 5분이 조금 지난 후에 Pod가 이관된다고 보면된다.

잃어버린 10초에 대해서는 로그를 찾아보았지만 단서가 없었다... (Verbose Level을 높여볼 순 있으나 너무 보기가 어려워 우선은 이정도로 만족하려한다.)