本記事はPostgreSQL on Kubernetes Advent Calendar 2018の9日目です。
昨日は「PostgreSQL on k8sで障害テスト(2) ストレージノード」ということで、PostgreSQL on Kubernetesの構成でストレージノードを落とした際の動きをテストしてみました。
今日はポッド障害のケースを整理してみたいと思います。
TL;DR
- PostgreSQL on Kubernetesの構成でポッド障害を起こして影響を確認してみた。
- PostgreSQLポッドが落ちた場合は当然サービス停止、復旧には想定以上に時間がかかった。
- Rook/Cephのポッド停止によるサービス影響はなし。
障害パターン（結果込み）
前回2回の結果と今回結果を受けた、PostgreSQL on Kubernetesの障害パターン表を以下にまとめます。
| 障害分類 | 障害部位 | 想定する動き | 結果 |
|---|---|---|---|
| ノード | 課題あり | ||
| 想定どおり | |||
| ポッド | PostgreSQL | サービス停止、PostgreSQLポッド再起動 | 想定どおり |
| Rook.Operator | サービス継続、Rookポッド再起動 | 想定どおり | |
| Rook.Agent | サービス継続、Rookポッド再起動 | 想定どおり | |
| Ceph.MON | サービス継続、Cephポッド再起動 | 想定どおり | |
| Ceph.OSD | サービス継続、Cephポッド再起動 | 課題あり |
k8sにおけるポッド障害って何？
今回テストにするにあたり、そもそもk8sにおけるポッド障害とは何を指すのかを確認しておきます。
ポッドの障害ケースを試す際に良く見られるのが、kubectl delete pod コマンドです。
しかし、使ってみると分かりますが、kubectl deleteでは即時に別のポッドが起動されます。
これはおそらく、KubernetesのAPIサーバにコマンドを投げた際、ポッド削除とメタデータ更新がされているため、すぐにリカバリが走る状態になっていると考えられます。
そのため、本来のポッド障害を想定した場合にはkubectl deleteではない方法で擬似障害を起こさなくてはならないのではないでしょうか。
その方法として、以下の3つを考えてみました。
- kubectl execでポッドに接続し、PID:1のプロセスをkill
- ポッドが稼動するノードに接続し、psコマンドで適当なプロセスをkill
- ポッドが稼動するノードに接続し、docker psで適当なコンテナを探してdocker stop
いろいろ試したのですが、今回は3.を試したいと思います。
PostgreSQLポッド障害
上の方針を踏まえ、PostgreSQLのポッド障害をテストしてみます。
手順は以下のようになります。
- pgbenchで3分のベンチマークを実行
- DBノードでPostgreSQLが稼動しているコンテナをdocker stop
- pgbenchが停止することを確認
- PostgreSQLのポッドが再起動され、復旧することを確認
ベンチマーク実行
こちらは想定どおり、手順2.のdocker stopがされた時点でベンチマークはabortしています。
$ kubectl exec -it pgtools-7(略) -c pgbench -- /usr/pgsql-10/bin/pgbench -h pg-rook-sf.default.svc -U bench -c 2 -T 180 -l --aggregate-interval=60 bench
starting vacuum...end.
client 1 aborted in command 10 of script 0; perhaps the backend died while processing
client 0 aborted in command 9 of script 0; perhaps the backend died while processing
(途中省略)
PostgreSQLコンテナをdocker stop
ベンチマークを実行しながら、docker stopするコンテナを探します。
$ sudo docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
8b71113b1e12 978b82dc00dc "docker-entrypoint..." 40 seconds ago Up 39 seconds k8s_pg-rook-sf_pg-rook-sf-0_default_3de2a8a4-fa0e-11e8-83f0-02786407b9a8_1
85c879676f67 rancher/pause-amd64:3.1 "/pause" 4 hours ago Up 4 hours k8s_POD_pg-rook-sf-0_default_3de2a8a4-fa0e-11e8-83f0-02786407b9a8_0
障害を発生させたいポッド：pg-rook-sf-0に相当するコンテナが2つ出てきます。
k8s_pg-rook-sf-0_default・・と、k8s_POD_pg-rook-sf-0_default・・です。
今回の検証環境ではKubernetesをRancher2.0を利用して構築していますので、IMAGEがrancher/・・となっているk8s_POD_pg-rook-sf-0_default・・がポッドに相当するコンテナ、もう一つのk8s_pg-rook-sf-0_default・・がPostgreSQLのコンテナ、だろうと予測します。
テストではPostgreSQLのコンテナ（k8s_pg-rook-sf-0_default・・・）をstopしてみます。
$ sudo docker stop k8s_pg-rook-sf_pg-rook-sf-0_default_3de2a8a4-fa0e-11e8-83f0-02786407b9a8_1
その結果、予想通りにPostgreSQLのポッドが停止し、Kubernetesによる自動復旧が走ります。
サービス停止時間は？
このケースではdocker stopによる擬似障害から、PostgreSQLポッドの再起動までどれぐらいかかるのかが気になる点です。
2度テストし他結果、停止時間は以下のようになっていました。
- 1度目は15秒
- 2度目は29秒
該当のStatefulSetのマニフェストは以下のようになっています。
livenessProbe:
tcpSocket:
port: 5432
initialDelaySeconds: 10
periodSeconds: 3
timeoutSeconds: 3
failureThreshold: 2
readinessProbe:
tcpSocket:
port: 5432
initialDelaySeconds: 5
periodSeconds: 3
timeoutSeconds: 1
successThreshold: 1
停止判定は3秒間隔で投げており、タイムアウト3秒*2回の6秒でチェックNGのはずなのですが、今回は遥かに時間がかかっています。
この辺りは時間を取って、細かくログを確認したほうが良さそうです。
PostgreSQLポッドの復旧を確認
起動時のPostgreSQLポッドを確認すると、以下のようなログが出力されています。
00:29:52.011 JST [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
00:29:52.011 JST [1] LOG: listening on IPv6 address "::", port 5432
00:29:52.046 JST [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
00:29:52.190 JST [25] LOG: database system was interrupted; last known up at 2018-12-08 00:21:18 JST
00:29:52.262 JST [25] LOG: database system was not properly shut down; automatic recovery in progress
00:29:52.308 JST [25] LOG: redo starts at 0/34CFFD30
00:29:52.672 JST [25] LOG: invalid record length at 0/3E5EA6B8: wanted 24, got 0
00:29:52.672 JST [25] LOG: redo done at 0/3E5EA690
00:29:52.672 JST [25] LOG: last completed transaction was at log time 2018-12-08 00:29:23.800195+09
00:29:52.770 JST [25] LOG: checkpoint starting: end-of-recovery immediate
00:30:05.182 JST [25] LOG: checkpoint complete: wrote 16384 buffers (100.0%); 0 WAL file(s) added, 0 removed, 9 recycled; write=10.381 s, sync=1.910 s, total=12.459 s; sync files=21, longest=1.684 s, average=0.090 s; distance=156586 kB, estimate=156586 kB
00:30:05.199 JST [1] LOG: database system is ready to accept connections
大した負荷をかけてないのでRedoのリカバリはすぐなのですが、その後end-of-recoveryのチェックポイントが走り、その時間が13秒ほどかかっています。
実際のコネクション再接続はこの後となってしまうため、サービス停止時間は現在の設定だと30秒から1分程度かかってしまうことになります。
Operator、Agent、MONのポッド障害
これらは上記と同じdocker stopで該当のコンテナを止めてみたのですが、即時復旧されました。
pgbenchによるベンチマークでもabortは発生せず、サービスにも影響ありません。
OSDポッド障害
では、ポッド障害の最後はOSDです。
結論からいうと、OSDのコンテナをdocker stopで止めてもpgbenchによるベンチマーク続行に影響は与えませんでした。
ただ、OSDはMONと違って、ポッドの再起動後にデータの再同期・リカバリが走ります。
今回のテストではポッドの再起動が失敗するケースがありました。
OSDコンテナの停止
まず、手順としてはこれまでと同様にpgbcenhで3分間のベンチマークを実行します。
その後、docker psでストレージノードのコンテナを確認し、OSDコンテナをdocker stopします。
この際もIMAGEがrancher/・・でないほうをstopします。
$ sudo docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
bd65349ce4d9 8005b7c5fc5b "ceph-osd --foregr..." 5 hours ago Up 5 hours k8s_osd_rook-ceph-osd-2-7c7b568bd-gwjch_rook-ceph_1a2a7dc9-fa0e-11e8-83f0-02786407b9a8_0
4d8b7aa7a0ac rancher/pause-amd64:3.1 "/pause" 5 hours ago Up 5 hours k8s_POD_rook-ceph-osd-2-7c7b568bd-gwjch_rook-ceph_1a2a7dc9-fa0e-11e8-83f0-02786407b9a8_0
$ sudo docker stop bd65349ce4d9
Cephの状態確認
上記でOSDを停止した後に、ceph statusで状態を確認してみます。
$ kubectl exec -it rook-ceph-tools-57f88967f4-fb66j -n rook-ceph -- ceph status
cluster:
id: 7d2ba914-6739-4e79-891a-59702e681ac4
health: HEALTH_WARN
1 osds down
1 host (1 osds) down
Degraded data redundancy: 1261/3783 objects degraded (33.333%), 100 pgs degraded, 100 pgs undersized
services:
mon: 3 daemons, quorum a,c,b
mgr: a(active)
osd: 3 osds: 2 up, 3 in
data:
pools: 1 pools, 100 pgs
objects: 1.26 k objects, 4.4 GiB
usage: 31 GiB used, 209 GiB / 240 GiB avail
pgs: 1261/3783 objects degraded (33.333%)
100 active+undersized+degraded
OSDが起動してきません。しばらく待っても結果は同じでしたので、OSDの起動ログを確認してみます。
2018-12-07 16:30:44.470 7f1ea31ef1c0 0 ceph version 13.2.2 (02899bfda814146b021136e9d8e80eba494e1126) mimic (stable), process ceph-osd, pid 14126
2018-12-07 16:30:44.470 7f1ea31ef1c0 0 pidfile_write: ignore empty --pid-file
starting osd.2 at - osd_data /var/lib/rook/osd2 /var/lib/rook/osd2/journal
2018-12-07 16:30:44.518 7f1ea31ef1c0 -1 Processor -- bind unable to bind to 10.42.5.21:7300/0 on any port in range 6800-7300: (99) Cannot assign requested address
2018-12-07 16:30:44.518 7f1ea31ef1c0 -1 Processor -- bind unable to bind to 10.42.5.21:7300/0 on any port in range 6800-7300: (99) Cannot assign requested address
2018-12-07 16:30:44.518 7f1ea31ef1c0 -1 Processor -- bind was unable to bind. Trying again in 5 seconds
特定のポートでIPがアサイン出来ないというエラーに見えます。
おそらくポッドの停止状態が中途半端になり、ネットワーク関連のリソースが解放されていないのでは？と思われます。
再度テストを行い、今度はポッド側のコンテナをSTOPしたところ、OSDポッドが正常に再起動されました。
このあたりが他のポッドとは動きが違ったところです。
Cephのリカバリ
OSDポッドが再起動されるとデータ再同期・リカバリが走ります。
その状況下でceph statusを実行すると以下のように表示されます。
$ kubectl exec -it rook-ceph-tools-57f88967f4-fb66j -n rook-ceph -- ceph status
cluster:
id: 7d2ba914-6739-4e79-891a-59702e681ac4
health: HEALTH_WARN
Reduced data availability: 1 pg peering
Degraded data redundancy: 327/3822 objects degraded (8.556%), 76 pgs degraded
services:
mon: 3 daemons, quorum a,c,b
mgr: a(active)
osd: 3 osds: 3 up, 3 in; 67 remapped pgs
data:
pools: 1 pools, 100 pgs
objects: 1.27 k objects, 4.5 GiB
usage: 31 GiB used, 209 GiB / 240 GiB avail
pgs: 1.000% pgs not active
327/3822 objects degraded (8.556%)
75 active+recovery_wait+undersized+degraded+remapped
23 active+clean
1 active+recovering+undersized+degraded+remapped
1 peering
io:
recovery: 35 MiB/s, 9 objects/s
しばらくたってから再度状況を確認し、HEALTH_OKとなっていれば復旧完了です。
まとめ
障害テストの最終回、ポッド障害をまとめてみました。
Rook/Cephのレイヤでは大きな問題はありませんでしたが、PostgreSQLの復旧時間が思ったよりもかかっていることが気になりますね。
ここはprobe設定を変えて、もう一度試してみたいと思います。
よろしくお願いします。