オレンジのトップページ

2019年11月12日火曜日

vSphere Web Client 6.7 に接続すると「503 Service Unavailable」エラーが発生する

この秋2019年9月から稼働し始めた某学校のvCenter Server 6.7への接続が503エラーになる障害が起きたので対策。1−2ヶ月順調に稼働していたのですが、v6.7はv6.5のマイナーアップデートだと思って安心していたのにこんな罠があったとは。昨日今日と対策したので記録。

環境はこんな感じです。

・ホスト HPの2ソケットサーバメモリ64GB x2台 ESXi 6.7.0 Update 3 (Build 14320388)
・vCenter Server 6.7 アプライアンス

これ今回ストレージはローカルストレージです。NASをなくした代わりにホストの方は結構がんばって性能を上げました。でも2台のホストサーバのどちらかが落ちたらと思うと、NASがあったほうが仮想マシンファイルが残るので気持ち安心だったですね。ハイパーコンバージドや2ノードVSANも流行っているようですがホストとストレージが1体はコワイかな、余談になりましたが。

症状:
vCenterを起動直後はアクセスできるものの、10分ほどで503エラーでアクセスできない。

直接の原因:
vCenterのイベントログ肥大

イベントログ肥大を引き起こした原因:
ESXi6.7.0 Update 3 (Build 14320388)のバージョンの不具合

以下解消手順を順を追って書きます。たぶん特定バージョンの不具合なので半年〜1年後にはこの情報は不要に、、、なっていると嬉しいですね。

対策1日め

肥大化したログのデータベース整理

まず見つかったのがこちら。サービスが立ち上がっているか確認しろというものでした。たしかにサービスはおっしゃるとおり落ちているのですが役に立たず。
https://kb.vmware.com/articleview?docid=2121043&lang=ja
VMware-KB「vSphere Web Client に接続すると「503 サービスを使用できません (503 service unavailable)」エラーが発生する (2121043)」

次に見つかったのがこちら。
http://friendsnow.hatenablog.com/entry/2018/10/07/104435
VCSA6.7 で「503 Service Unavailable」エラー
>私が経験した事象では、vpxd を上記手順及び、VCSA 再起動により起動しても、すぐに Stopped になりました。
>原因はデーターベースの肥大化に起因するものと判明しました。対処方法は以下のとおりです。

これだ。早速確認。
vCenterにSSHで入ってシェルを起動
> shell
サービスvpxdが止まっていたら起動
# service-control --status
# service-control --restart vpxd
# service-control --start vpxd
# service-control --status vpxd


/storage/seat 領域を確認、ほぼ満杯。
# df -h /dev/mapper/seat_vg-seat
Filesystem                Size  Used Avail Use% Mounted on
/dev/mapper/seat_vg-seat  9.8G  8.5G  747M  93% /storage/seat


postgresに接続して肥大化しているテーブルを縮小します。
# cd /opt/vmware/vpostgres/current/bin 
# ./psql -d VCDB -U postgres 

テーブルのサイズが大きい順に10個表示させます。元記事では5個表示でしたが結構たくさんありました。
VCDB=# SELECT nspname || '.' || relname AS "relation", pg_size_pretty(pg_total_relation_size(C.oid)) AS "total_size" FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname NOT IN ('pg_catalog', 'information_schema') AND C.relkind <> 'i' AND nspname !~ '^pg_toast' ORDER BY pg_total_relation_size(C.oid) DESC LIMIT 10; 

      relation       | total_size 
---------------------+------------
 vc.vpx_event_arg_56 | 250 MB
 vc.vpx_event_arg_60 | 250 MB
 vc.vpx_event_arg_64 | 247 MB
 vc.vpx_event_arg_55 | 244 MB
 vc.vpx_event_arg_59 | 242 MB
・
・
・

VCDB=# truncate table vc.vpx_event_arg_56 cascade;
VCDB=# truncate table vc.vpx_event_arg_60 cascade;
と順に削除していきます。消してもう一度表示させて。を繰り返します。
全部で20−30個ほど消したかな。数十MB以上のログのテーブルを消して容量チェックします。


root@photon-machine [ /opt/vmware/vpostgres/current/bin ]# df -h /dev/mapper/seat_vg-seat
Filesystem                Size  Used Avail Use% Mounted on
/dev/mapper/seat_vg-seat  9.8G   83M  9.2G   1% /storage/seat

と8.5G→83Mに劇的に減らせました。当分vCenterが落ちることはないでしょう。

vCenterのSYSLOG設定

またすぐテーブルは満杯になるでしょうから、syslog取って原因確認できるようにします。
https://vCenterのIPアドレス:5480/ にログインして「syslog → 転送設定」でsyslogホストを指定します。

ログがsyslogサーバに出力されていることを確認して、時間も遅くなったので翌日に期待しつつ1日目の作業を終了します。


対策2日め

ログの中身

明くる日の今日の朝からチェックしていきます。syslogサーバにもう300M超のログがたまっています。
vCenterの方も、SSHログインして見ると83Mまで減っていたログのテーブルが12時間ほどでまた316Mまで増えています。vCenterが重かったのもきっとこのことが原因でしょうか。ログ肥大化の原因をなくさないといけないとあらためて決意して、何がここまでログを大きくしているのか確認していきます。


syslogサーバに多量に出ているログはこれ。時間が13時って、、、?作業途中でvCenterのタイムゾーンをGMTからJSTに修正したからか、それとも昨日作業のいちばん最初にsyslog設定したのだったかのどちらかだと思います、ちょっと忘れましたがそれは置いておいて。hardware sensorアラームって書いてますね。
Nov 11 13:29:35 photon-machine vpxd[4607] Event [38319679] [1-1] [2019-11-11T04:29:35.720596Z] [vim.event.AlarmSnmpCompletedEvent] [info] [] [Datacenter] [38319679] [Alarm 'Host hardware sensor state': an SNMP trap for entity 192.168.xx.yy was sent]
Nov 11 13:29:35 photon-machine vpxd[4607] Event [38319680] [1-1] [2019-11-11T04:29:35.720692Z] [vim.event.EventEx] [error] [] [Datacenter] [38319680] [Alarm 'Host hardware sensor state' on 192.168.xx.yy triggered by event 38319134 'Sensor -1 type , Description Intel Corporation Xeon E7 v3/Xeon E5 v3/Core i7 Integrated Memory Controller 1 Channel 0 Thermal Control #23 state assert for . Part Name/Number N/A N/A Manufacturer N/A']

今度はVMware-KBがマッチ。
https://kb.vmware.com/s/article/74607
Excessive Hardware health alarms being triggered for "Sensor -1 type" on ESXi hosts running vSphere 6.7 U3 (74607)
のページにThis article provides information and workaround for the hardware health alarms getting triggered (for sensor -1 type) on ESX hosts running vSphere 6.7U3 build-14320388. って書いている。ちょうどうちのESXiのバージョンです。SEATパーティションサイズが95%越えるとvCenterが起動しなくなると書いてあるのも、そのまんまです。
Additionally, these events can result in the vCenter database increasing in size leading to insufficient disk space issues such as vCenter unavailability once the SEAT partition size goes above the 95% threshold.

対応は wbemサービスを無効にすればいいと書いてある。停止してもいいのか?
https://kb.vmware.com/s/article/1025757?lang=ja
注:CIM エージェントはハードウェア健全性情報を提供するプロセスです。このサービスを無効にすると、ハードウェアの健全性ステータスが無効になります。

こーれーはー。ずっと止めておくのはまずいんじゃん?でも仕方ないので提案どおり止めます。年末にでもESXiをアップデートしたらまた有効にできるか確認しよう。

vCenterにSSHログインして、shellを起動して次のコマンドを実行。
esxcli system wbem set --enable false

実行直後から多量のログは出なくなりました。

もとに戻すときは反対にこうしろと書いています。
esxcli system wbem set --enable true


以上です。

感想〜♪

ESXi 6.7 U3 build-14320388のリリースは8月末だったので、これを適用したユーザで、ハードウェアからは同じようなログが出ている環境だときっと今頃みんな同じ目にあって503エラーで接続できなくなっていそう。うちはホストが2台構成だったのでエラーになるまで1-2ヶ月かかったけれど、標準の3台構成だともっとログが早くたまるんじゃないかな。

6.7U3-14320388のリリース日:
https://docs.vmware.com/jp/VMware-vSphere/6.7/rn/vsphere-esxi-67u3-release-notes.html
ESXi 6.7 Update 3 | 2019 年 8 月 20 日 | ISO ビルド 14320388

このVMware-KB のリリース日
Created: Sep 4, 2019
Last Updated: Oct 21, 2019
https://kb.vmware.com/s/article/74607

だったのでそうかもしれない。

0 件のコメント:

コメントを投稿