[Troubleshoot] 久々の我が家環境大惨事

俺はな、ESXiのバージョンアップがしたかっただけなんだ

全てはこれが始まりでして、現在稼働しているESXiサーバの内1台をESXi6.5->6.7にバージョンアップしようと考えました。で、影響が出そうなVMを停止の上で、とある一台のESXiサーバに対して6.7最新パッチを適用する形でのアップグレードを実施しました。

すると、以下のような感じで芋づる式というか、次々とトラブルが起きました。

メモリが減ってる
起動してみるとあら不思議、それまで128GBメモリを積んでいたサーバ、改めて見返してみると96GBしかメモリが認識されていない・・・そんなバカなとiLOを開いてみるとメモリが1枚ご臨終召されてました。
加えて、デュアルチャネル構成のために道連れでさらにもう1枚メモリが「不使用」状態になり、合計32GBのメモリ容量を失って居るではないですか・・・とは言え、動作は継続できそうなので、その内メモリは買い換えるとして、サーバは継続稼働させることにしたのです。
サーバが落ちる
なにやらサーバを立ち上げてる過程で、空耳?と言うレベルで「ピーピーピー」という音がサーバ設置部屋から聞こえてきたのです。んん?と気になって、実機を見てみるとなんと言うことでしょう・・・・・サーバがPOST画面になってるじゃないですか。
どうやらWarningを出したメモリが悪さをしてCPUにエラーを吐かせて、結果としてPanicRebootが走ったようです。
慌てて電源OFFして、ヘロヘロの体で嫁様の助けを借りながら障害発生したメモリを取り外して起動。取り敢えずどうやら動作できそうだというのは分かりました。
Mastodonのデータベースが起動しない
その次が悲惨で、なんとストレージも一通り上げたところでMastodonのインスタンスを起動するのですが、全く起動する気配がない。調べてみると、いつまでたってもMastodonのデータベースが開局しなさそうで。
Kubernetes上で動かすPostgreSQLは、その起動途中でディレクトリのオーナー権をホストから奪取するためにデータディレクトリ全体に対してchownコマンドを実行するのですが、どーもこれに時間がかかりすぎていると。
Cephの応答がおかしい
で、バックエンドストレージであるCephを確認してみると、えらく応答が遅い。これはどういうことだと調べるところから、長い戦いが始まったわけでありますね。

Cephで吐き出されていたエラー

ドタバタしていてDashboardの画面は拾えませんでしたが、後に何とかログを拾えたのでこれを転載します。

2020-03-15 10:59:32.510 7fc405cf9700  0 
	log_channel(cluster) log [WRN] : Health check update: Long heartbeat ping times on back interface seen, 
	longest is 4082.940 msec (OSD_SLOW_PING_TIME_BACK)

2020-03-15 10:59:32.510 7fc405cf9700  0 
	log_channel(cluster) log [WRN] : Health check update: Long heartbeat ping times on front interface seen, 
	longest is 3206.453 msec (OSD_SLOW_PING_TIME_FRONT)

2020-03-15 10:59:36.012 7fc405cf9700  0 
	log_channel(cluster) log [WRN] : Health check update: 1 slow ops, oldest one blocked for 51 sec, 
	mon.eins has slow ops (SLOW_OPS)

主に出ていたのは上記のようなエラーです。どうも眺めてみるとmonプロセスがどっかのOSDがスタックしてるよと言うのを出しているようでした。この時点で、ESXiやVMの負荷を眺めてみたり、各ノードのvmstatを見たりiostatを見たりするわけですが、負荷は至っておとなしく。

ただ、メモリ使用量が全体的に増大していたのでスワッピングが発生しており、これが原因か?と言う気もしたので、全ノードのswapをoffに設定した上で、fstabからもswap設定を解除したりしましたが、現象は改善せず。

その後、色々あの手この手ストレージの移し替え等やるのですが、これまた改善の気配なし。

chown処理は終わったけど

chown処理が終わったのがどうやら午前6:30頃だったようで、その後はPostgreSQLも立ち上がってきたのですが、やっぱりどーも処理が遅い。データベースなんてまともに動いてる気配がしない上、下手すると一部のストレージオペレーションが5分以上スタックしている・・・・こりゃスローダウンとか言うカワイイ言葉じゃ済まないぞ?と思いながら、引き続きトラブルシュートを継続する私。

ようやく「原因は4号機か?」って気づき始める私。

2020-03-15 10:58:39.035 7fc4034f4700  1 
	mon.eins@0(leader).osd e1157 prepare_failure osd.3 192.168.100.114:6802/1928 
	from osd.1 192.168.100.112:6800/2325 is reporting failure:1

2020-03-15 10:59:31.012 7fc405cf9700 -1 
	mon.eins@0(leader) e1 get_health_metrics reporting 1 slow ops, 
	oldest is osd_failure(failed timeout osd.3 192.168.100.114:6802/1928 for 23sec e1157 v1157)

いまいちどことどこの間で不具合が起きてるの?というのは流れるログの中ではよく分からず、ログを一度出力させてテキストエディタに吐き出させ、そして並べて見るとあることに気づくわけでして。

処理が全部192.168.100.114上で止まってる?」的な。

4号機の配置先は最初にESXi6.7へバージョンアップさせた仮想ホスト上で動作しているVMです。一応ホストに対するpingを撃ち込んだりしていたのですが、特に応答に問題はないと思ったら

73 packets transmitted, 69 received, 5% packet loss, time 73010ms
rtt min/avg/max/mdev = 2.846/17.363/248.692/49.176 ms

あら?全体的な統計を見たら5%もパケットロス起こしてるじゃないのさ。
こんなんまともなわけがないわけで、他のホストでみると、特にパケットロスは発生しない・・・

ESXiサーバとスイッチ間の接続

接続構成

我が家仮想基盤の接続構成は上記の通りとなっています。太線が10GbE、細線が1GbE接続となっています。
まず、Ceph4号機のサービスセグメント側との疎通がうまくいってないぽいことが分かったので、仮想スイッチの切り替えを行いました。Ceph4号機はESXi2号機で動いてましたので、この仮想スイッチを10GbEラインから1GbEラインに切り替えたところ、ステータスが

Health_WARN -> Health_OK と言う形に一気に変わりました。

おお、これはサービスセグメント側にある10GbEラインのどっかで不具合が起きてるな?と言うのがこの時点ですぐに分かった次第です。

考えられる問題

パターンとしては以下のような感じですね。

  • ドライバの問題・・・・ESXi6.7へ引き上げたことでドライバの不具合が発生した?
  • NICの問題・・・・・・NICのハード障害が起きて通信断が発生するようになった?
  • スイッチに問題・・・・アライドスイッチもしくはMikrotikのスイッチに何らかの不具合が出た?
  • ケーブルに問題・・・・ケーブルの物理故障?

で、切り分けをやった結果は以下の通りとなりました。

  • Mikrotikスイッチ間の疎通確認・・・・①
    全ての通信においてパケット欠落なし
  • GbE経路上のスイッチ間疎通確認・・・・②
    全ての通信においてパケット欠落なし
  • サービス向け10GbEのスイッチ感疎通確認・・・・③
    やっぱりパケット欠落あり。欠落率:4-10%程度
    • ESXi1号機->2号機・・・・・・・・欠落あり
    • ESXi3号機->2号機・・・・・・・・欠落あり
    • ESXi1号機->3号機・・・・・・・・欠落なし
    • ESXi2号機->3号機・・・・・・・・欠落あり

上記の結果から、どうやら2号機側のサービスLANに接続された10GbE側に何らかの問題がある・・・と言うのが分かりました。ただ、Mikrotikスイッチに接続してる側は全く問題ないことから、恐らくはNICそれ自体の問題ではなさそうに見えます。そこで、最終的には10GbEで使用しているDACに何らかの問題があるかもと言うことで、これをGbEのSFPと余ってたOM-2ケーブルに切り替えて接続し直したところ、最終的な不具合(断続的にvSphereHAエージェントエラーも出てる状況があった)も解消され、これが故障箇所だと言うことが明白となりました。

取り敢えずは暫定復旧として、色々周辺のハード周りを修理していこうと思うわけですが、いやはやこんだけいくつも色々壊れてるとちょっと辛いですなー・・・とか感じたり。それでも何とか破損箇所が洗い出せたのは良かったです。

Linuxのping応答には気をつけよう。

今回、ping応答を確認しながらトラブルシュートをしてた訳なんですが、ping応答の時ちょっと気をつけるポイントがあります。ロスった所が明示的に出てこないのです。

64 bytes from 192.168.100.114: icmp_seq=1 ttl=64 time=248 ms
64 bytes from 192.168.100.114: icmp_seq=2 ttl=64 time=4.31 ms
64 bytes from 192.168.100.114: icmp_seq=3 ttl=64 time=6.33 ms
64 bytes from 192.168.100.114: icmp_seq=4 ttl=64 time=2.84 ms
64 bytes from 192.168.100.114: icmp_seq=7 ttl=64 time=5.20 ms
64 bytes from 192.168.100.114: icmp_seq=8 ttl=64 time=5.23 ms
64 bytes from 192.168.100.114: icmp_seq=9 ttl=64 time=11.2 ms

よくよく考えたらそもそも同一セグメント通信でこんだけばらつきがあるってどうなん?と言うのに気づくわけですが・・ハイライトしているところを見れば分かるんですが、2パケットほど応答が出来てないことが分かります。Windowsのpingでは応答が来なければTimeoutが出ますし、何が何でもEcho Replyが来るまで待つため、そこの応答遅延で異常に気づくんですが、Linuxだとこのような感じで、意外と目立ちません。

実際の仕事でも、ping応答させながらvMotionしてみたりといったテストをすることはあるんですが、その時も意外とこれを見落として「パケットロストなし」と判定して、後でログ証跡を眺めたときに「あれあれ?」ってなることも多く、こうした出力特性はきちんと押さえておいて損はないかもです。