はじめに

Kubernetes v1.29.5をkubespray v2.25.0から導入しました。kube-vipとの関連だろうとは思うのですが、ときどきIngressへの接続時にコネクションが張れずに502エラーが発生しています。

このままではサービスインできないだけでなく、他のk8sクラスターをアップグレードすることもできなくなるので原因について調べていきます。

kube-vip自体はとても便利でkubectlのアクセスを認証済みユーザーに開放しているクラスターでは、可用性を確保するためにKubespray v2.24.0からkube-vipを使ったapi-serverポートのVIP化を行っています。

なお常に502エラーが発生するような状況であれば、まずアプリケーションが正しく構成されているか、Serviceのselectorが適切にPodを指しているかといった設定を見直してください。

状況の把握

フロントエンドプロキシーのnginx側ではproxy_next_upstreamを設定しているので、単純な接続ミスであれば再送されますが、エラーの様子からはHost Unreachableなどのパケットがk8sクラスター側から送信されているようにみえます。

332024/06/04 23:38:19 [error] 137992#137992: *3406 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.1.10, server: example.com, request: "GET /grafana/ HTTP/1.1", upstream: "https://192.168.200.99:443/grafana/", host: "example.com"
2024/06/04 23:38:19 [error] 137992#137992: *3408 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.1.10, server: example.com, request: "GET /webapp/ HTTP/1.1", upstream: https://192.168.200.99:443/webapp/", host: "example.com"

Uptime Kumaでモニターしても異常が発生するのはフロントエンリバースプロキシーからIngressにproxy_passで渡しているリクエストだけで、フロントエンドのnginx単体や、proxy_passでK8sのノード単体で簡易的にWebサーバーを実行している(k8s, Ingressを経由しない)サービスに接続しても失敗することはありません。

ちなみにノード単体上では次のようなスクリプト(a.rb)をnohup ./a.rb &のように実行しています。

a.rb

#!/usr/bin/ruby
#
require 'webrick'

server = WEBrick::HTTPServer.new(Port: 8080, DocumentRoot: "/usr/share/doc/info/html/")
server.start

異常が発生する前後でのリバースプロキシーノードのARPテーブルをみてみると次のように変化しています。

ip neighコマンドの出力の変化

## 正常時
192.168.200.64 dev enp3s0 lladdr 00:22:4d:a8:b8:15 REACHABLE
192.168.200.63 dev enp3s0 lladdr 00:22:4d:a8:ba:4f REACHABLE
192.168.200.158 dev enp3s0 lladdr 08:bd:43:b9:a8:e7 REACHABLE
192.168.200.62 dev enp3s0 lladdr 00:22:4d:a8:ba:4c REACHABLE
192.168.200.61 dev enp3s0 lladdr 00:22:4d:a8:ba:40 REACHABLE
192.168.200.99 dev enp3s0 lladdr 00:22:4d:a8:ba:4c REACHABLE

## 障害発生直後
192.168.200.64 dev enp3s0 lladdr 00:22:4d:a8:b8:15 DELAY
192.168.200.63 dev enp3s0 lladdr 00:22:4d:a8:ba:4f REACHABLE
192.168.200.158 dev enp3s0 lladdr 08:bd:43:b9:a8:e7 STALE
192.168.200.62 dev enp3s0 lladdr 00:22:4d:a8:ba:4c DELAY
192.168.200.61 dev enp3s0 lladdr 00:22:4d:a8:ba:40 STALE
192.168.200.99 dev enp3s0 lladdr 00:22:4d:a8:ba:4c STALE

このタイミングで同時にtcpdumpでICMPパケットもモニターしていたので、その出力が次のようになっています。

tcpdump -i enp3s0 -n -v icmp の出力

tcpdump: listening on enp3s0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
11:36:00.749678 IP (tos 0xc0, ttl 64, id 35462, offset 0, flags [none], proto ICMP (1), length 88)
    192.168.200.62 > 192.168.200.1: ICMP host 192.168.200.99 unreachable, length 68
        IP (tos 0x0, ttl 63, id 57322, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.200.1.55328 > 192.168.200.99.443: Flags [S], cksum 0x68de (correct), seq 410361499, win 64240, options [mss 1460,sackOK,TS val 2210840007 ecr 0,nop,wscale 7], length 0
...

nginxのproxy_next_upstream_triesに指定している回数だけ繰り返されていて、まぁこれはしょうがないなぁといった感じです。

ARP関連の対策

とりあえずICMPパケットを送信しているnode2(192.168.200.62)を黙らせてみます。

$ sudo kubectl cordon node2
$ sudo kubectl drain node2 --force --ignore-daemonsets --delete-emptydir-data

この後、node2を再起動しました。

するとnode1(192.168.200.61)からicmp redirectメッセージが送信されています。

12:20:28.575869 IP (tos 0xc0, ttl 64, id 5958, offset 0, flags [none], proto ICMP (1), length 68)
    192.168.200.61 > 192.168.200.1: ICMP redirect 192.168.200.99 to host 192.168.200.99, length 48
        IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto TCP (6), length 40)
    192.168.200.1.50300 > 192.168.200.99.443: Flags [R], cksum 0x8cd9 (correct), seq 1239482680, win 0, length 0

node2をuncordonしてクラスターに戻すと、引き続き現象が発生するものの、ICMPパケットは観測されません。

リバースプロキシーとして動作しているフロントエンドのnginxのログをみると、node2の再起動前後で次のようなエラーが記録されています。

フロントエンドnginxのログから抜粋

## node2の再起動前
2024/06/05 12:17:38 [error] 148052#148052: *1896 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.1.10, server: example.com, request: "GET /grafana/ HTTP/1.1", upstream: "https://192.168.200.99:443/grafana/", host: "example.com"

## node2の再起動後
2024/06/05 12:28:35 [error] 148053#148053: *1962 peer closed connection in SSL handshake (104: Connection reset by peer) while SSL handshaking to upstream, client: 192.168.1.10, server: example.com, request: "GET /webapp/ HTTP/1.1", upstream: "https://192.168.200.99:443/webapp/", host: "example.com"
2024/06/05 12:34:36 [error] 148052#148052: *2010 SSL_write() failed (104: Connection reset by peer) while sending request to upstream, client: 192.168.1.10, server: example.com, request: "GET /webapp/ HTTP/1.1", upstream: "https://192.168.200.99:443/webapp/", host: "example.com"

どちらも502ステータスが返ってきますが、理由はそれぞれ別々です。再起動によってICMP Host Unreachableメッセージはとりあえず消えました。

これまではTLSの証明書と鍵ファイルは1つにだけ指定していて、個別アプリケーションでは指定してきませんでしたが、全てのIngressオブジェクトにSSLの証明書を明示的に指定するようにして様子をみます。

NAMESPACE       NAME          CLASS   HOSTS         ADDRESS                                                       PORTS     AGE
ingress-nginx   default-tls   nginx   example.com   192.168.200.61,192.168.200.62,192.168.200.63,192.168.200.64   80, 443   2d14h
minitoring      grafana       nginx   example.com   192.168.200.61,192.168.200.62,192.168.200.63,192.168.200.64   80, 443   2d14h
webapp          webapp        nginx   example.com   192.168.200.61,192.168.200.62,192.168.200.63,192.168.200.64   80, 443   23h

この変更をしてからはしばらく平穏な時間が過ぎています。

もう一方の原因の対策

しばらくするとSSL Handshake関連のエラーが出たのでingress-nginx-controllerのログを確認します。

あらかじめ daemonset/ingress-nginx-controller を編集し、コマンドラインの引数に -v=3 を追加しています。-v=5にしてしまうと障害が発生してすぐにログを確保しても肝心なところがバッファからあふれてしまっていたので'3'に留めています。

W0605 05:00:35.170262       7 backend_ssl.go:47] Error obtaining X.509 certificate: no object matching key "myns/webapp-tls" in local store

これは先ほどIngressにTLS関連の設定を入れた際にSecret/webapp-tlsを設定するのを忘れていました。

これを設定してからingress-nginx-controllerを再起動します。

$ sudo kubectl -n ingress-nginx rollout restart daemonset ingress-nginx-controller

リスタートのタイミングで502エラーが返ってきましたが、そのまま様子をみます。

ログを確認するとエラーなく全てのIngressに対応するTLS関連のファイルがロードされていました。

I0605 05:20:41.272285       7 backend_ssl.go:67] "Adding secret to local store" name="myns/webapp-tls"
I0605 05:20:41.369159       7 nginx.go:307] "Starting NGINX process"

これが直接の原因ではないと思いますが、クラスターをリスタートしたことで、しばらくはエラーが記録されず時間が過ぎています。

MetalLBとkube-vipのLoadBalancer設定が原因

しばらくすると問題が発生するのでKubesprayの設定を見直していくと、kube-vip周りの設定でおかしなところがありました。

MetalLBを使ってLoadBlancerを管理していますが、kube_vip_services_enabled: trueを設定していて、これがkube-vipを使ってLoadBalancerを管理するというものなので機能が重複しています。

二重に立ち上げて不具合があるとは書かれていないようですが、問題が収束したのは次のように全てのflagをtrueにしていたものからkube_vip_enable_node_labelingとkube_vip_services_enabledをfalseにしたところ問題が収束しました。

# Kube VIP
kube_vip_enabled: true
kube_vip_arp_enabled: true
kube_vip_controlplane_enabled: true
kube_vip_address: 192.168.200.60
loadbalancer_apiserver:
  address: "{{ kube_vip_address }}"
  port: 6443
kube_vip_interface: enp0s25
kube_vip_services_enabled: false
kube_vip_dns_mode: first
kube_vip_cp_detect: false
kube_vip_leasename: plndr-cp-lock
kube_vip_enable_node_labeling: false

kube_vip_enable_node_labelingはNodeにVIPの情報を付与するものなので実害はないはずです。

再びkube_vip_services_enabledだけをtrueにして前後の様子を詳しく観察してみます。

Serviceオブジェクトが大量に作り変えられている

次のコマンドを実行するとtype: LoadBalancerが指定されているServiceオブジェクトが大量に作り続けられています。

$ sudo kubectl get --all-namespaces svc -w

もちろん通常は一度作成されたServiceオブジェクトが作り続けられるということはありません。

metallbのcontrollerのログをみてみます。

kubectl -n metallb-system logs pod/controller-666f99f6ff-h2tgf -fの出力抜粋

...
"}
{"caller":"service_controller.go:60","controller":"ServiceReconciler","level":"info","start reconcile":"minio/my-minio-console-lb","ts":"2024-06-05T22:35:17Z"}
{"caller":"main.go:101","event":"serviceUpdated","level":"info","msg":"updated service object","ts":"2024-06-05T22:35:17Z"}
{"caller":"service_controller.go:103","controller":"ServiceReconciler","end reconcile":"minio/my-minio-console-lb","level":"info","ts":"2024-06-05T22:35:17Z"}
{"caller":"service_controller.go:60","controller":"ServiceReconciler","level":"info","start reconcile":"ingress-nginx/ingress-nginx","ts":"2024-06-05T22:35:17Z"}
{"caller":"main.go:101","event":"serviceUpdated","level":"info","msg":"updated service object","ts":"2024-06-05T22:35:17Z"}
{"caller":"service_controller.go:103","controller":"ServiceReconciler","end reconcile":"ingress-nginx/ingress-nginx","level":"info","ts":"2024-06-05T22:35:17Z"}
...

短時間でreconcileが繰り返されている様子が観察できます。

だいたい様子は分かったのでkube_vip_services_enabledはfalseにしておき、node_labelingはtrueに戻しておきます。

ここまでで障害の原因がkube-vipとmetallbの両方がLoadBalancerタイプのServiceオブジェクトを書き換え続けるreconcileループが無限に発生していたことが原因だと分かりました。

おそらくServiceオブジェクトの再定義の一瞬にアクセスがあった場合には、Routingができずに接続が切られるのではないでしょうか。

もう少し調査するべき点は残っていますが、ひとまず対処は分かったのでkubesprayに両方を同時に有効化すると問題があることを知らせておきたいと思います。

https://github.com/kubernetes-sigs/kubespray/issues/11271

さいごに

原因が分かるとキーワードが明確になるので、これまで発見できなかった関連するIssueに到達する可能性が高まります。

https://github.com/metallb/metallb/issues/2177 looping "end reconcile" and ARP requests für LB-IP looping #2177

このIssuesで最終的にkube-vipのLoadBalancerサービスが問題だと結論づけられています。

この設定を有効にすること自体は難しくないので、潜在的に問題を含んでいるクラスターが存在しているかもしれません。

今回の教訓は自分でカスタムコントローラーを作成する時には自前のCRDを作成することが大切だという点です。

一般的なServiceオブジェクトのようなものを監視対象としてしまうと、似たような動作をするコントローラーがマッチポンプ的に更新処理の無限ループを引き起してしまう可能性がかなり高いということが分かりました。

MetalLBやkube-vipのようなサービスはとても便利で、システムの他の要素に影響与えるとはあまり考えていませんでしたが、これに限らず注意していきたいと思います。