※ 本投稿は vExperts Advent Calendar 2020 の 12/8 分を担当しております。
vExpert Advent Calendar 2020 はこちらです。ぜひ他のエントリーもお読み下さい!!
過去のvExpert Advent Calendarへのリンクもあります。
vExpert Advent Calendar 2020 https://adventar.org/calendars/5343
vExpert Advent Calendar は昨年に引き続き2年連続2回目の参加です。
昨年はVMTNの個人ブログページに書いた記事を投稿させていただきました。
今年もそのつもりだったのですが、今年の11月にVMTNのコミュニティプラットフォームが一新され、現在ブログ機能が利用不可になってしまい、
私がこれまでに書き溜めていたブログにはアクセスができなくなってしまいました。
早期の復旧を切に祈っております。
したがって今年の記事はQiitaで書かせていただきました。
Qiitaは初挑戦となりますので、何かと拙い部分があるかと思いますがご容赦いただければと思います。
#はじめに
###トラブル発生！！まず何をする？
vSphereやVMware製品に限らず、IT製品の構築作業や運用をしていれば、何らかのエラーや失敗に遭遇することがありますね。
その場合どのように対処するかは人それぞれだと思いますが、大半の方は以下の三つのどれかになると思います。
・エラーメッセージを見てググる
・サポートに問い合わせる
・自分でログを見てトラブルシューティングする
私は平素テクニカルサポートとしてVMware 製品に携わっておりますので、主にログを見ることとなります。
しかしながら、一口でログを見る、といっても、果たして見るべきログはどこにあるのでしょうか？
ログ自体に関する情報は乏しい
この記事を執筆するにあたって、「vSphere Log Location」 というキーワードで引掛けてみたところ、以下の記事が見つかりました。
https://docs.vmware.com/en/VMware-vSphere/6.7/com.vmware.vsphere.monitoring.doc/GUID-832A2618-6B11-4A28-9672-93296DA931D0.html
https://kb.vmware.com/s/article/1021804
逆にいうと、それ以外の情報はすぐには見つかりませんでした。
率直に言って、この内容では全然足りませんｗｗｗ
私自身の経験から言っても、この2つの記事で紹介されるログ以外にも、vSphere環境で出力されているログはたくさんあります。
さらにいえば、仮に見るべきログファイルがわかったところで、ログの出力を解釈できるかは別問題です。
つまるところ、VMwareの無償の公開情報の範囲で、ログからトラブルシューティングするのは、ハードルが高いということです。
もちろん、上記の記事の内容と一般的なIT知識で解決できる問題もありますが、うまく解析できずに諦めてしまった方もいらっしゃるかもしれません。
本記事では事象発生からログファイルを特定するまでのTipsの一つをご紹介できればと思います。
常に利用可能な汎用性の高い手法ではなく、そういう風にして特定できる場合もある、程度の期待値でお読みください。
#VCSAのログ解析
今回取り上げる事象
下記のエラーメッセージを例にご紹介いたします。
状況としては仮想マシンを新規に作成しようとしたところ上記のエラーが出て失敗した、というシナリオです。
正直なところ、有識者であればこのメッセージだけでどこが怪しいのか、どのログを見るべきなのかはわかるようなメジャーなエラーだと思いますが、執筆にあたり事象の再現と復旧が容易で、影響も少ないのでこの事象にしました。
事象発生時刻を特定
事象発生時刻を特定するのにはjournalctlをよく利用します。
別にログを見なくても、vSPhere Clientの「最近のタスク」から時間を秒単位で確認してもよいのですが、
この後に確認するvpxd.logは一秒間に多量のログを吐くこともありますので、できればサブ秒程度の時刻を確認したいところです。
journalctlで事象発生時刻近辺を見ると、より詳細なEventやAlarmの発生時刻を特定できるので非常に便利です。
journalctlはログファイルではなくコマンドで出力されますので、vc-supportには/var/log配下ではなく、commands配下にその出力があります。
今回の例ですと以下のような出力が確認できました。
Dec 07 09:20:50 tsevxrail-vcsa.cpsd.local vpxd[3433]: Event [58520230] [1-1] [2020-12-07T09:20:50.922926Z] [vim.event.TaskEvent] [info] [VSPHERE.LOCAL\Administrator] [VxRail-Datacenter] [58520230] [Task: Create virtual machine]
これでEvent 発生時刻は 2020-12-07T09:20:50.922926Z と分かります。
当然ながらタイムゾーンには注意ですね。タイムスタンプの一番最後にZがついているのでGMTだとわかります。
vpxd.log をみる
vCenterの動作関連や、vSphere Clientの操作関連でエラーになった時、特に見るべきログに心当たりがない場合は、とりあえずvxpd.logを見るところから始めるのが良いと思います。
場合によってはvpxd.logだけで解決できることもありますし、そうでなくても次に見るべきログのヒントになる情報を見つけられる可能性が高いです。
前のステップで確認した詳細時刻をもとに絞り込んでいくと、以下のメッセージを見つけることができました。
①
2020-12-07T09:20:50.936Z warning vpxd[03477] [Originator@6876 sub=Default] Failed to connect socket; <io_obj p:0x00007f9e6830f620, h:75, <TCP '127.0.0.1 : 38420'>, <TCP '127.0.0.1 : 8190'>>, e: 111(Connection refused)
②
2020-12-07T09:20:50.936Z error vpxd[03463] [Originator@6876 sub=VmProv opID=khsdo6kc-453435-auto-9pvg-h5:70071331-51-01] Get exception while executing action vpx.vmprov.InvokePrechecks: N5Vmomi5Fault11SystemError9ExceptionE(Fault cause: vmodl.fault.SystemError
③
2020-12-07T09:20:50.946Z info vpxd[03463] [Originator@6876 sub=Default opID=khsdo6kc-453435-auto-9pvg-h5:70071331-51] [VpxLRO] -- ERROR task-116952 -- group-v3 -- vim.Folder.createVm: vmodl.fault.SystemError:
--> Result:
--> (vmodl.fault.SystemError) {
--> faultCause = (vmodl.MethodFault) null,
--> faultMessage = ,
--> reason = " PBM error occurred during PreCreateCheckCallback: Connection refused: The remote service is not running, OR is overloaded, OR a firewall is rejecting connections."
--> msg = ""
--> }
--> Args:
-->
②と③は、メッセージの内容から仮想マシン作成のタスクが失敗した際の出力と想定されます。
この二つはopIDも共通なので同じタスクに対して出力されたものなのだと想像できますね。
③の出力中に、reasonの項目に「Connection Refused」という文言が見られます。
これが原因のようです。
これは、VPXDのサービスが、別のサービスに接続しに行った際にConnection Refusedでエラーになってしまった、ということが想像できます。
VCSAの内部では様々なサービスが稼働しており、お互いにAPIなどで情報を収集したり、リクエストを送信したりしています。
VCSAもVPXDが中心となって、VCSA内部の様々なサービスと連携することで動作しています。
それがConnection Refusedになる、ということは、どうやら正しく動作していないサービスがあるようです。
そのサービスを特定するヒントが ① の出力にあります。
エラーになっている通信を見つける
① の出力を再度見てみると、
2020-12-07T09:20:50.936Z warning vpxd[03477] [Originator@6876 sub=Default] Failed to connect socket; <io_obj p:0x00007f9e6830f620, h:75, <TCP '127.0.0.1 : 38420'>, <TCP '127.0.0.1 : 8190'>>, e: 111(Connection refused)
となっていますね。
注目すべきはポート番号です。
これはTCP ポート 38429 を利用するプロセスが、TCP ポート 8190 を利用するプロセスと通信していると解釈できます。
※IPアドレスはどちらもループバックアドレスなのでVCSA内部の通信と分かる。
どちらがクライアントでどちらがサーバなのかについては、たいてい数字の小さいほうがサーバです。
クライアント側で使用するTCPポートは動的に割り当てられるのに対し、サーバ側で利用するポートは固定なので、比較的小さい（10000以下）、かつ切りのいい数字が用いられることが多いです。
つまりここまでの流れを整理すると、新規の仮想マシンを作成する際にVPXDがポート8190を利用するプロセス（サービス）と通信をしようとしたが、Connection Refusedになったために、失敗したと想定されます。
ここで、rhttpproxy.log も見てみました。
rhttpproxyはVCSAの各サービス間の中継をするサービスです。重要なサービスなので覚えておいて損はないです。
正しく動作していないサービスがある場合は、rhttpproxy.log にも痕跡が残ることがあります。
実際に、rhttpproxy.log を 8190 で grep してみたところ、同様のConnection Refusedが大量に出ていました。
今回は割愛しますが、Connection Refusedが出始めた時刻を探ることで、ポート8190を利用するプロセスがいつからおかしくなったのかを絞り込むことができる場合もあります。
では話を戻しまして、ポート8190を利用するプロセス（サービス）は何なのでしょうか？
ポート番号からサービスとプロセスを特定
ここまでの流れから、ポート8190を利用するプロセスは、ポート8190でLISTENしているサービスであると想定されます。
VCSAのサービスがポート8190を固定的に利用しているのであれば、ググれば出てきそうですね。
案の定、簡単に以下のページにたどり着きました。
https://docs.vmware.com/en/VMware-vSphere/6.5/com.vmware.vsphere.security.doc/GUID-ECEA77F5-D38E-4339-9B06-FF9B78E94B68.html
↑のページの情報によると、ポート8190を利用するサービスは、「VMware vSphere Profile-Driven Storage Service」のようです。
これがどのようなサービスなのか、どのログを見ればいいかも、ググれば情報が出てきますが、それだとTipsにならないので割愛します。
ポート8190を利用するサービスの情報を入手するために、実際のこのポートを利用中のプロセスを特定してみます。
Linux環境でTCPポートとプロセスの対応を確認する方法はいくつかあると思いますが、ここではnetstatを利用します。
具体的には以下のコマンドで特定します。
# netstat -apon | grep 8190
tcp 0 0 127.0.0.1:8190 0.0.0.0:* LISTEN 17159/vmware-sps.la off (0.00/0/0)
これで8190を利用する（LISTENする）プロセスがわかりました。
プロセスIDは 17159 のようです。
さらに ps コマンドで情報を取得します。
# ps auxwww | grep 17159
root 17159 17.1 3.2 3481176 535564 ? Sl 10:10 0:26 /usr/java/jre-vmware/bin/vmware-sps.launcher -Xmx709m -XX:CompressedClassSpaceSize=128m -Xss256k -XX:ParallelGCThreads=1 -Dxml.config=sps-spring-config.xml -Dpbm.config=pbm-spring-config.xml -Dsms.config=sms-spring-config.xml -Dvslm.config=vslm-spring-config.xml -Dcommon.config=common-spring-config.xml -XX:+ForceTimeHighResolution -XX:+PrintTenuringDistribution -verbose:gc -Dcatalina.home=/storage/sps/tomcat -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/vmware/vmware-sps/ -XX:ErrorFile=/var/log/vmware/vmware-sps/java_error%p.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintReferenceGC -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024K -Xloggc:/var/log/vmware/vmware-sps/vmware-sps-gc.log -Djava.security.properties=/etc/vmware/java/vmware-override-java.security -Djava.ext.dirs=/usr/java/jre-vmware/lib/ext:/usr/java/packages/lib/ext:/opt/vmware/jre_ext/ -XX:ThreadStackSize=256 -classpath /usr/lib/vmware/common-jars/tomcat-annotations-api-8.5.45.jar:/usr/lib/vmware/common-jars/tomcat-embed-core-8.5.45.jar:lib/XmlSchema-1.4.3.jar:lib/admin-interfaces-1.0.jar:lib/authentication-framework-1.0.jar:lib/axiom-api-1.2.9.jar:lib/axiom-impl-1.2.9.jar:lib/axis2-adb-1.5.1.jar:lib/axis2-kernel-1.5.1.jar:lib/axis2-transport-http-1.5.1.jar:lib/fst-2.45.jar:/usr/lib/vmware/common-jars/jackson-core-2.9.9.jar:lib/javassist-3.19.0-GA.jar:lib/json-20160810.jar:lib/objenesis-2.4.jar:lib/axis2-transport-local-1.5.1.jar:lib/castor-core-1.3.jar:lib/castor-xml-1.3.jar:lib/cis-common-1.0.jar:lib/cm-common-1.0.jar:lib/commons-collections4-4.1.jar:lib/commons-lang3-3.4.jar:lib/dozer-5.5.1.jar:lib/featureStateSwitch-1.0.0.jar:lib/guava-19.0.jar:lib/invsvc-client-1.0.jar:lib/protostuff-collectionschema-1.4.4.jar:lib/invsvc-client-v3-vmodl-1.0.jar:lib/invsvc-core-1.0.jar:lib/junit-4.10.jar:lib/local-kv-vmodl-1.0.jar:lib/mail-1.4.jar:lib/neethi-2.0.4.jar:lib/pbm-1.0.jar:lib/pbm-versions-1.0.jar:lib/pbm-vmodl-1.0.jar:lib/query-vmodl-1.0.jar:lib/reflect-vmodl-1.0.jar:lib/samltoken-1.0.jar:lib/protostuff-core-1.4.4.jar:lib/protostuff-api-1.4.4.jar:lib/protostuff-runtime-1.4.4.jar:lib/service-common-1.0.jar:lib/sms-1.0.jar:lib/sms-versions-1.0.jar:lib/sms-vmodl-1.0.jar:lib/vslm-1.0.jar:lib/vslm-versions-1.0.jar:lib/vslm-vmodl-1.0.jar:lib/sps-versions-1.0.jar:lib/sps-vmodl-1.0.jar:lib/lookupservice-bindings-client-1.0.jar:lib/sso-adminsdk-1.0.jar:lib/client-domain-controller-cache-1.0.jar:lib/sso-adminserver-client-bindings-1.0.jar:lib/stax2-api-3.0.1.jar:lib/storage-commons-1.0.jar:lib/vasa-client-v1-1.0.jar:lib/vasa-client-v2-1.0.jar:lib/vasa-client-v3-1.0.jar:lib/vasa-client-v4-1.0.jar:lib/vasa-versions-1.0.jar:lib/vasa-vmodl-1.0.jar:lib/vim-versions-1.0.jar:lib/vim-vmodl-1.0.jar:lib/vlsi-client-1.0.jar:lib/vlsi-core-1.0.jar:lib/vlsi-server-1.0.jar:lib/vmware-endpoint-certificate-store-1.0.jar:lib/vmware-vmca-client-1.0.jar:lib/woodstox-core-asl-4.0.5.jar:lib/wsdl4j-1.6.2.jar:lib/wstClient-1.0.jar:lib:server/config:conf:resources:/opt/vmware/vpostgres/current/lib/postgresql.jdbc4.jar:/usr/lib/vmware-cm/lib/vmodl-cm.jar:/usr/lib/vmware/common-jars/bcprov-jdk15on-1.60.jar:/usr/lib/vmware/common-jars/commons-beanutils-1.9.4.jar:/usr/lib/vmware/common-jars/commons-codec-1.6.jar:/usr/lib/vmware/common-jars/commons-collections-3.2.2.jar:/usr/lib/vmware/common-jars/commons-configuration-1.6.jar:lib/commons-httpclient-3.1.jar:/usr/lib/vmware/common-jars/commons-io-1.4.jar:/usr/lib/vmware/common-jars/commons-lang-2.6.jar:/usr/lib/vmware/common-jars/commons-logging-1.1.3.jar:/usr/lib/vmware/common-jars/custom-rolling-file-appender-1.0.jar:/usr/lib/vmware/common-jars/httpclient-4.3.3.jar:/usr/lib/vmware/common-jars/httpcore-4.3.2.jar:/usr/lib/vmware/common-jars/jna.jar:/usr/lib/vmware/common-jars/joda-time-1.6.2.jar:/usr/lib/vmware/common-jars/log4j-1.2.16.jar:/usr/lib/vmware/common-jars/platform.jar:/usr/lib/vmware/common-jars/slf4j-api-1.7.28.jar:/usr/lib/vmware/common-jars/slf4j-log4j12-1.7.28.jar:/usr/lib/vmware/common-jars/spring-aop-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-beans-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-context-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-core-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-expression-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-oxm-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-web-4.3.25.RELEASE.jar:/usr/lib/vmware/common-jars/spring-webmvc-4.3.25.RELEASE.jar:/usr/lib/vmware-vpx/sps/lib/vcdbconfig-1.0.jar:/usr/lib/vmware/common-jars/commons-dbcp-1.4.jar:/usr/lib/vmware/common-jars/commons-pool-1.6.jar com.vmware.sps.StorageMain
どうやらJavaで動くアプリケーションのようです。コマンドラインの引数やオプションなどを見ることで大体のログファイルの場所やサービスの名前などが推測できます。
実際に https://kb.vmware.com/s/article/2109881?lang=ja を確認すると、vmware-spsというサービスがあるようなのでこのサービスに何らかの問題があると容易に想像できます。
サービスの一覧については、上記のKBを見なくとも、service-control --status --all などでも確認可能ですね。
プロセスからログファイルを特定
では、最後にこのサービスが利用するログファイルを特定します。
先ほど実行した ps コマンドの出力からも vmware-sps-gc.log というログの存在が示唆されますが、これは求めるログではありません。
これは Java のガベージコレクションのログなので、見ることはほとんどないと思います。（私は見たことないです）
Java のガベージコレクションの説明については割愛します。興味がある人はググってみてください。
真に求めるログを特定するにはこのプロセスが開いているファイルを調べればわかります。
このプロセス（PID 17159）が開いているファイルの一覧は、そのプロセスの fd(ファイルディスクリプタ) を見ればわかります。
具体的には以下のようにします。
# ls -l /proc/17159/fd/ | grep log
l-wx------ 1 root root 64 Dec 7 10:11 1 -> /storage/log/vmware/vmware-sps/sps-runtime.log.stdout
l-wx------ 1 root root 64 Dec 7 10:11 107 -> /storage/log/vmware/vmware-sps/sps.log
lr-x------ 1 root root 64 Dec 7 10:11 185 -> /usr/lib/vmware-vpx/sps/resources/static-content/sms/SmsMessageCatalog.zip
l-wx------ 1 root root 64 Dec 7 10:11 2 -> /storage/log/vmware/vmware-sps/sps-runtime.log.stderr
l-wx------ 1 root root 64 Dec 7 10:11 3 -> /storage/log/vmware/vmware-sps/vmware-sps-gc.log.0.current
lr-x------ 1 root root 64 Dec 7 10:11 86 -> /usr/lib/vmware/common-jars/commons-logging-1.1.3.jar
lr-x------ 1 root root 64 Dec 7 10:11 92 -> /usr/lib/vmware/common-jars/log4j-1.2.16.jar
lr-x------ 1 root root 64 Dec 7 10:11 95 -> /usr/lib/vmware/common-jars/slf4j-log4j12-1.7.28.jar
今回のオチ、そして余談
仮想マシン作成失敗の原因は？
ようやく見るべきログファイルが特定できました。
このログファイルをみれば、このサービスが動作不良を起こしている理由のヒントが得られる可能性があります。
結論を言うと、今回このサービスは停止していました。
そのため、VPXDはこのサービスと通信ができずにタスクが失敗した、というわけです。
vmware-sps というのは、vSAN が利用するストレージポリシーを司るサービスです。（vSAN 専用というわけじゃないです）
実は今回失敗した仮想マシンの作成のタスクは、vSAN データストア上に仮想マシンを作成しようとしていました。
この vmware-sps サービスが利用不可の場合は、vSAN データストア上で、どのようにオブジェクトを配置するかなどのポリシーを決定できないため、仮想マシンの作成に失敗していた、というわけです。
余談：Connection Refused について
今回の事象はサービスが停止していた（＝サービスがLISTENしてなかった）ことが原因でした。
しかしながら、オチに違和感を感じた人もいるかもしれません。
サービスが停止していて、LISTEN してないのに、なぜ Connection Refused なのでしょうか？
サービスが稼働していないということは、TCPポートの利用するプロセスがいなかったということなのに、いったい誰が「Refuse」したのでしょうか？
その答えは TCP 自体にあります。
TCPの仕様については、RFC793を見るのが一番確実だとと思ってます。（ただし理解するのは難しい。。）
まずTCPにおいて、LISTEN していない、とはどういう状態なのでしょうか？
LISTEN もしてないし、誰も使用していないなら、状態（State）は「何もない」のでしょうか？
いいえ、TCPにおいてStateがないということはありません。
RFC793を読んでみると、ポートが誰からも利用されておらず、LISTEN もしてない状態は、CLOSED に相当します。
CLOSED の説明として以下が確認できました。
CLOSED - represents no connection state at all.
では、この CLOSED 状態のポートにSYN セグメントを送り付けたらどうなるのでしょうか？
RFC793 には、CLOSED 状態のポートがセグメントを受信した場合の挙動として以下の記載があります。
SEGMENT ARRIVES
If the state is CLOSED (i.e., TCB does not exist) then
all data in the incoming segment is discarded. An incoming
segment containing a RST is discarded.An incoming segment not containing a RST causes a RST to be sent in response.The
acknowledgment and sequence field values are selected to make the
reset sequence acceptable to the TCP that sent the offending
segment.
つまり、CLOSED のポート（LISTEN してないポート）に RST フラグの無いセグメントが送られると、そのレスポンスとして、 RST フラグを付けて返すという仕様のようです。
そして、RST フラグを受け取った側は、以下の判断をします。
second check the RST bit,
SYN-RECEIVED STATE
If the RST bit is set
If this connection was initiated with a passive OPEN (i.e.,
came from the LISTEN state), then return this connection to
LISTEN state and return. The user need not be informed.If this connection was initiated with an active OPEN (i.e., came from SYN-SENT state) then the connection was refused, signal the user "connection refused".In either case, all segments
on the retransmission queue should be removed. And in the
active OPEN case, enter the CLOSED state and delete the TCB,
and return.
つまり、LISTEN してないポートに対して SYN セグメントを送った Client は、RST フラグをうけとり、
それをユーザ側にConnection Refused として通知（Signal）する、ということですね。
以上が、サービスが停止しているのも関わらず、Connection が Refuse される仕組みでした。
利用してないポートが、RST を返す、というのはもしかしたらセキュリティ的には、よろしくないかもしれませんが、いろいろメリット・デメリットありそうで、難しいところかもしれませんね。
#おわりに
思ったより長くなってしまいましたが、これを持ちましてvExperts Advent Calendar 2020 の 12/8 の投稿とさせていただきます。
終わってみれば、Qiita のスキルよりも文章スキルのほうが問題ありな気がしてきましたが。。
また、繰り返しにはなりますが、今回ご紹介した方法は、常に利用可能な汎用性の高い手法ではなく、こういう風にして特定できる場合もある、程度の内容であることはご容赦いただければと思います。
特に fd (ファイルディスクリプタ) でのログファイル特定はアテにしすぎてはいけません。
サービスやプロセスが常にログファイルを開き続けているとは限りません。その方法で特定できない場合もあります。
来年は今年よりもより良い年になって、そしてまたvExpertのAdvent Calendarに参加できるように祈っています。
（VMware ブログの復活も切に祈ってます）
明日の Advent Calendar は、masotsuka さんです。
vExpert Advent Calendar 2020 https://adventar.org/calendars/5343