自分用備忘録として書いた。
トラシューをやってる間、怒りがマッハでタイプ音が糞うるさかった。すみません。
同じ轍を踏まぬよう、そして私と同じトラブルで悶え苦しんでいる全てのシステム管理者に・・・。
※推測で話を進めているフシが結構あります。
　「これ違うんじゃね?」と思った箇所があれば、コメントお願いします。

事象

ESXiサーバのアップデートを実施したところ、ゲストOS(Windows Server 2008 R2)の時刻がずれた。
で、原因究明した話。

因みに今回不具合が発生した環境は以下のような感じになっている。

OS	バージョン
ESXi	5.1
Windows Server	2008 R2 Standard(WORKGROUP)

詳しい経緯

定期的にやっているメンテナンスで、ESXiのアップデートとパッチあてを実施した。
ウチでは主要なESXiはアクティブとスタンバイの2台で構成しているので、vMotionでゲストを片寄せしてそれぞれアップデートをし、パッチをあてた。
メンテナンスも無事終わり、ゲストを元のESXiに戻したら、 その1日後にESXiに載っているWindowsゲスト全部のNTPがなんかずれたっぽい。

以前からゲストOSの再起動時に同じような現象が起きていたのだけれど、その頃は時間がなかったので、再起動の度に適当にNTPを合わせるという対応で騙し騙し運用をしてきた。
因みにこいつは最近ESXiを含めたハードウェアのリプレースを済ませたばかりだ。
ぶっちゃけリプレースをすれば解消するかなーとかぼんやり思っていたのでちょっとショック。
ていうかゲストの再起動とか時刻変わるようなことはしていないし。なんで起きたのか謎。
以前メンテした時はなかったんだけど。むしろメンテの度に起きてたら今頃ナレッジとして確立させているはずだ。
だからもうこの機会にどうなってるかちゃんと調査することにした。
どうせ障害報告書もあげなくちゃいけないし・・・。

そして原因究明へ・・・。

ログを見る

とりあえず時刻がずれてたWindowsゲストを確認する。
まずはそれの確認からだが・・・。
時刻が合っている・・・。

ということは元々ずれていた時刻が元に戻ったのか。
現状を把握したらとりあえずイベントビューアーを見る。

バーっと見ているとシステムログに何やらそれっぽいメッセージが・・・。
キャプチャは載せられないので文章のみ記載。

ソース: Kernel-General
イベント ID: 1

説明:
システム時間は ‎2016‎-‎03‎-‎02T03:11:16.151178800Z から ‎2016-‎03‎-‎02T03:22:32.900000000Z に変更されました。

何故か時刻が11分進んでしまっている。
一体どうして・・・何がトリガーなんだ・・・これ・・・。
でも、午前3時?
と思ったらUTCなのね・・・。
+09:00で、障害通知が発報した時刻とおおよそ一致する。
で、なんで時刻が進んだのか・・・。
というか何故元からずれていたのか。
困った時のGoogle先生。
とにかくググッて解決だ！

BIOS時刻が優先される?

とりあえず windows kernel-general 1 vm のキーワードでググッてみる。
そしたら SKYARCHさんのとこで似たような症状を書いたブログがヒット。
以下の事が書いてあった。

WindowsTimeServiceでNTP設定を有効にしても
RTCとシステム時刻のズレが大きい場合は OSがRTCをシステム時刻に設定する模様。。。

RTC・・・ってなんだろう。
ブログ内で参考にしているMicrosoftのナレッジ (KB946033)を見てみると、以下のような記載が。

高精度イベントタイマ (HPET) がサポートされている Windows Vista ベースのコンピュータを使用します。コンピュータを数時間実行した後に、システム時刻が BIOS 時刻と数秒異なっていることがあります。
(中略)
NTP サーバーに対するアクティブな接続が存在しない場合、システム時刻が BIOS クロックと同期され、時刻の差異が 60 秒を超えた場合に、システム時刻が BIOS クロックに合わせて自動的に修正されます。

なるほど。
RTCというのはBIOSが参照している時刻の事らしい。
そしてReal Time Clockの略語らしい。

で、システム時刻とBIOS時刻が大きくずれていた場合、BIOS時刻が優先されて設定されると・・・。
とは言えナレッジに書いてあるのはあくまでもWindows Vistaベースのコンピュータだ。
Windows Server 2008 R2 とはまた勝手が違う可能性もあるが・・・。
とは言え貴重な情報には変わりない。実際にSKYARCHさんのブログでもAWSのホストを変更したら直ったという風に記載されている。
とりあえずこの線を攻めていくことに。
引き続きGoogleさん頼み。

ESXiのシステム時刻 → ゲストのBIOS時刻?

今度は vm システム時刻　bios時刻　windows というキーワードでググる。
こちらの技術ブログがヒットしたので、拝見させてもらう。

そもそもハードウェアクロックとシステムクロックとは
サーバーの電源が落ちたとしても、ある程度時間を刻むことができないと、次回起動時のOSの時間のずれが大きくなり、動作に支障をきたす可能性がある。したがって、外部電源に頼らずに、システムボード上のボタン電池にて時刻を刻む機能があり、それがハードウェアクロックとなる。

なるほど。どうやら BIOS時刻 = ハードウェアクロック らしい。
こういうのってなんか色んな呼び方あるよなあ・・・。
そしてハードウェアクロックは、コンピュータの停止時にも内蔵電池で時刻を刻み続けることで、次回起動時に時刻のずれをなるべくなくすことができる。といったところか。

そしてその後にかなり有用な情報が書いてあった。

同期タイミングは以下の通り。
[a. VM：システムクロック]　←VM起動時にb→aに同期、VM停止時にa→bに同期
[b. VM：ハードウェアクロック]　←VM起動時にc→bに同期
------------------------------
[c. ESX：システムクロック]　←ESX起動時にd→cに同期、ESX停止時にc→dに同期
[d. ESX：ハードウェアクロック]　←通常は内蔵電池で時間を維持

VMにおけるハードウェアクロックは仮想BIOSが持つ時間
VM停止後のハードウェアクロック情報はBIOSは保持せず消失
VM起動時にESXのシステムクロックをVMのハードウェアクロックとして同期する

なんと、ESXiのシステムクロックはそのままゲストOSのハードウェアクロックになってしまうらしい。
更に調べるとMicrosoftの公式なナレッジにも、ハードウェアクロックとシステムクロックの関係について同様の説明が記載されていた。

Windows を起動すると、Windows はリアルタイムクロック (RTC) メモリに直接アクセスし、RTC の日付および時刻の値を用いてコンピュータの日付および時刻を設定します。

ということは、Windowsゲストが乗っているESXiの時刻が狂っている可能性がある。
対象サーバは Windows NT 系を指定しているので今回該当のサーバとはまた違うのだが、こうした基幹部分の機能がそうそう変わるとも思えない。
恐らくWindows Server 2008 R2 でも機能的には同様だろう。
早速確認してみると・・・。

・・・。
・・・・・・。
なるほど、ビンゴか・・・。

ESXiの時刻がきっかり11分遅れている。
NTPサーバを確認すると、指定しているIPアドレスの第3オクテットが違っていて存在しないIPアドレスを指していた。
因みにスタンバイ側のESXiは正規のNTPサーバが設定されていた。
糞ッ！！糞がッ！！！ド畜生めェッ！！！！！！！
このESXiを設定したのは誰だぁっ！！！！
・・・憤っても過ぎたことは仕方ない。
リプレース時に設定をちゃんと確認しなかった自分も悪いのだ。

しかし、本当にこれが理由だろうか。
確かに、ESXiの時刻はずれていた。
これが影響していることは恐らく事実だろう。
だが、参照した技術ブログには、こう書かれていた。

[a. VM：システムクロック]　←VM起動時にb→aに同期、VM停止時にa→bに同期
[b. VM：ハードウェアクロック]　←VM起動時にc→bに同期

そう、ハードウェアクロックとシステムクロックを同期させる動作は VM起動及び停止時 となっているのだ。
Microsoftのナレッジでも同様だ。
Windows起動時にRTCを用いてコンピュータの日付および時刻を設定する と書いてある。
ESXiメンテ時にゲストOSの再起動は実施していない。
これもうわけわかんねえな。

この後めちゃくちゃ検索した。

仮想マシンの特定イベント後に VMware Tools がハードウェアクロックと時刻を同期する?

Windowsの仕様とVMの仕様と両方の線で検索していくことにした。
で、 vm windows　時刻同期　設定 で検索したところ、VMwareのナレッジがヒット。
しかし最初に引っかかった時、あろうことか流し見して見逃してしまう。
これがいけなかった。流し見してしまったことで多分2時間くらい無駄にした。
その後別の技術ブログが見つかり、確認のために再度ナレッジへと飛んだのだが・・・。
いやホント、糞無駄な時間を費やした。萎える。

それはともかくとして、ナレッジには以下の事が書いてあった。

VMware Tools のコントロールパネルで、[時刻同期] チェックボックスはオフになっていますが、次のようなシンプトムが発生することがあります。

仮想マシンをサスペンドする場合、その仮想マシンを次回レジュームするときに、ホストに合わせて時刻が同期されます。

時刻は、vMotion を使用した仮想マシンの移行、スナップショットの作成、スナップショットの復旧、仮想ディスクの圧縮、または仮想マシンでの VMware Tools サービスの再起動（仮想マシンの再起動を含む）を行うときに再同期されます。

(中略)
[時刻同期] チェックボックスでは、仮想マシンの実行中に時刻を定期的に再同期するかどうかのみを制御します。このチェックボックスがオフの場合でも、時刻が不正確になりがちないくつかの特定のイベントの後で、VMware Tools はデフォルトで仮想マシンの時刻を同期します。

もう・・・どうして・・・こんな仕様に・・・。
絶望して魔女になりそう。
どうやら特定のイベントが走った時に、ゲストの時刻を同期する処理を ~~VMware Tools~~ ESXi が実行してくれるみたいです。
その中にはvMotionも入ってる。
多分、というか絶対にこれだろうよ。
ゲストOSをスタンバイのESXiに片寄せして、戻した時、全部のゲストOSを指定してvMotionしたし・・・。
多分それで負荷が掛かったか何かで「時刻がずれたかも」というのを検知して ~~VMware Tools~~ ESXi がゲストの時刻をハードウェアクロック(ESXiのシステムクロック)と合わせてくれたんだろう。
大きなお世話だ。畜生余計なことしやがって。
(2016/03/31) 上記を一部修正しました。

ともあれ原因は突き止めた。
要はESXiのNTPサーバのIPアドレスを修正して同期を掛けてやれば良いわけだ。
とりあえず修正してNTPの再起動を掛ける。
その内元の時刻に戻るだろうと考え、一旦様子見。

・・・3時間後に確認したが、全然変わんねえ。
もうめんどくさくなったので手動で大まかな時刻を合わせることに。
多分その内直るんだろうが、こういったことは早めに修正しておくことが多分大事だ。多分。
で、手動で合わせた。
もう万事解決だろう・・・。
あとは障害報告書を上げて終わりとしよう・・・。
そう思っていた時期が、僕にもありました。

ESXiの時刻を進めた分Windowsゲストの時刻が変動した。

一件落着・・・と思いきや、1時間後に再度障害通知が発報。
もう定時なんだけど・・・。帰りたいんだけど・・・。

もう一度Windowsゲストを確認すると、え・・・また11分進んでる・・・。
システムログには最初と同じようなログが。
もう勘弁してほしい。
原因はESXiの時刻修正をしたためだろう。というかそれしか考えられない。
えぇ・・・一体全体どういうことなの・・・。
謎すぎて絶望しかない。もうソウルジェム真っ黒。

泣きながらとにかくググったところ、Microsoftのフォーラムにほぼ同様の症状について質問をしている方がいた。
③が発生したトラブルと同様の症状だ。

そしたらアンサーとしてこんな記載が。

言い過ぎな部分はありますが、Windowsでは、「未調整のシステムクロックはRTCよりも不正確」という古い実装の前提で構成されていて、したのKBからも、Windows Timeサービスが正常稼働していればシステムクロックのみを調整し、Windows Timeが正常動作していなければ、1時間に1回(条件が合致すれば)システムクロックがRTCに時刻を合わせる、という動作になるのではないでしょうか。
(中略)
仮想化ソリューションの基での動作を気にかけていらっしゃるようですが、仮想化ソリューション固有の動作に依存する可能性が高いので、切り分けて考えたほうがよろしいかと。(3)のコンテキスト(文脈)だと、ホストマシンの時刻変更=ゲストマシンのRTC変更、という認識でしょうが、そういうことでいいのでしょうか？また、ゲストマシンのOSにインストールされた「最適化ツール」(Hyper-Vだと統合ツール)は一般にはOS実装とは無関係に時刻同期を行います。

Windows Timeが正常動作していなければ、1時間に1回(条件が合致すれば)システムクロックがハードウェアクロックに時刻を合わせるらしい。
フォーラムのアンサーで参照されているMicrosoftのナレッジ (KB232488)にも同じ事が書いてあった。

Windows の起動後、Windows のタイムデーモンが約 1 時間に 1 回実行されます。タイムデーモンは Windows と RTC の時刻を比較します。この 2 つの時刻の差が 1 分以上の場合、Windows は RTC と一致するように時刻と日付を変更します。タイムデーモンの実行間隔を変更することはできません。
(中略)
Windows 2000 ベースのコンピュータで Windows タイムサービスが実行されている場合、Windows の起動後に Windows のタイムデーモンを約 1 時間に 1 回実行することはできません。

Windows のタイムデーモン と Windows タイムサービス って別物なのかしら・・・。
文脈からして別物っぽいけど・・・?
ここらの違いは探してもよくわからなかった。
誰か記載されているドキュメントあったら教えて下さい。

文脈から読み取ると、以下の様な違いがあるらしい。
Windows のタイムデーモン：
　ハードウェアクロックを元にシステムクロックを合わせる機能
Windows タイムサービス　：
　NTPを使いシステムクロックを合わせる機能

SKYARCHさんが参考にしていたナレッジにも似たようなことが書いてあったな。
で、Windowsゲストを確認したのだが、Windows Timeサービスは普通に動いている。
てことはこっちじゃないのか・・・。
というかそもそもシステムクロックをハードウェアクロックに同期させるということなら11分もずれる必要はないはずなのだ。
手動で分単位に合わせたのだから、ずれると言ってもせいぜい数秒～1分以内といったところだろう。
少し気掛かりがあるとすれば、このナレッジの対象にWindows Server 2008 R2がないというところだけだが・・・。

もう一方の回答だが、ゲストマシンのOSにインストールされた「最適化ツール」(Hyper-Vだと統合ツール)は一般にはOS実装とは無関係に時刻同期を行うらしい。

VMware製品だと、恐らく VMware Tools がこれに当たると思われる。
ということはVMwareの問題か・・・?
わからないけど・・・。

帰りたいゲージMAXだが、調査再開である。

Windows Timeサービスは動作していない?

何か手掛かりないかとイベントビューアーを確認していると、こんなメッセージが。

ソース: W32Time
イベント ID: 36

説明:
使用可能なタイムスタンプがタイム サービス プロバイダーによって提供されなかったため、タイム サービスは 86400 秒間、システム時刻を同期していません。
タイムサービスは、タイム ソースと同期できるようになるまで、ローカルのシステム時刻を更新しません。
ローカル システムがクライアントの時刻サーバーとして機能するように構成されている場合は、タイムソースとしてクライアントにアドバタイズすることを止めます。
タイム サービスは継続してタイム ソースとの同期を試みます。詳細については、他の W32time イベントのシステム イベント ログを確認してください。
’w32tm /resync’ を実行すると、時刻の同期を即座に強制実施できます。

前々からずっと出ているこのメッセージ。
大体週一ペースでこいつはログに姿を見せる。
なんなんだろうとずっと気にはなっていたのだけど、まあただの警告だし、実害も(多分)出てないっぽいし、このままでもいいだろうと放っておいたメッセージだ。
今まで気にも止めていなかったけど・・・。

ふと、思った。
こいつ出てるってことは Windows Timeサービスって動いてないのか?
いやまさか・・・。だってサービス見ても「開始」って書いてあるし・・・。
ただ、86400秒以上時刻同期をしていないと書いてある。
86400秒・・・。分にして1440分・・・。
時間にして24時間・・・丸一日ということだ。
で、週一出るということを考えると、こいつは週に一度しか時刻同期をしていないということになる。
Windowsのデフォルト設定がこれなのだろうから問題ないと思うが、警告として出るということは、あまりよろしくないということだろう。デフォルト設定のくせに・・・。
ていうかWindows Timeサービスが動いていないとなれば、上の方であげた Windows Timeが正常動作していなければ、1時間に1回(条件が合致すれば)システムクロックがハードウェアクロックに時刻を合わせる という挙動になるんじゃないか?

シコシコ検索すると、Microsoftのナレッジがヒットした。

Windows 7 および Windows Server 2008 R2 のスタンドアロン環境で、Windows Time サービスのスタートアップの種類を [手動] から [自動] に変更しても、システムを起動すると、Windows Time サービスは起動直後に停止して、以下のイベントログが記録されます。
Copied!
ログの名前: System 
ソース: Service Control Manager
イベント ID: 7036
レベル: 情報
Windows Time サービスは 実行中 状態に移行しました。
Copied!
ログの名前: System 
ソース: Service Control Manager
イベント ID: 7042
レベル: 情報 
Windows Time サービスに 停止 コントロールが正常に送信されました。 指定された理由: 0x40030011 [オペレーティング システム: ネットワークの接続 (計画済み)]
Copied!
ログの名前: System
ソース: Service Control Manager
イベント ID: 7036 タスクのカテゴリ: なし
レベル: 情報 
Windows Time サービスは 停止 状態に移行しました。

だそうだ。
しかし、確認しても上記のようなログはシステムログに出ていない。

だが、更にドキュメントを読んでいくとと、原因欄に以下のようなことが書いてあった。

Windows Time サービスは、既定のトリガーとして ActiveDirectory ドメイン環境に属しているかどうかにより起動と停止が判定されます。つまり、ActiveDirectory ドメイン環境に属している場合は、トリガー起動サービスによって Windows Time サービスが開始され、ActiveDirectory ドメインに属していない場合は、Windows Time サービスが停止されます。

なお、トリガーサービスの設定内容は、以下の sc qtriggerinfo コマンドを実行することにより確認できます。
Copied!
sc qtriggerinfo w32time

サービス名 : w32time 
サービスの開始
ドメインの参加状態 : 1ce20aba-9851-4421-9430-1ddeb766e809 [ドメインに参加済みです]

サービスの停止
ドメインの参加状態 : ddaf516e-58c2-4866-9574-c3b615d42ea1 [ドメインに参加していません]

sc qtriggerinfo というコマンドは「サービスのトリガー情報を取得するコマンド」らしい。
引数に w32time を指定すれば Windows Time サービスの開始停止のトリガーが出力される。
上のような結果になれば、ドメインに参加している場合はサービスが開始し、参加していなければサービスが停止する 状態にあるということがわかるようだ。

早速障害通知の出たサーバで試したところ、上と全く同じ結果が出力された。
今回のサーバはドメイン環境ではなく、WORKGROUPで動かしている。
つまりWindows Time サービスは停止している・・・?

ドキュメントにもそう書いてあるし、そういうことなのだろう。
サービスは「開始」になってるけどな！！！
どういう仕様なんだよ・・・これ・・・。

とりあえず、 Windows Timeサービスは停止している ということで話を進めていくことに。
しかし、まだまだ足りない。
NTPが動作していないと、システムクロックをハードウェアクロックに合わせにいく。というのは上であげた BIOS時刻が優先される? に書いてある通りだ。
また、Microsoftのフォーラムにも書いてあったが、Windows Timeが正常動作していなければ、1時間に1回(条件が合致すれば)システムクロックがハードウェアクロックに時刻を合わせるらしい。
同じことが起こるならば、やはり、数秒～1分以内でずれは収まるはずなのだが・・・。
恐らくここからはVM側の話になるだろうなあ・・・。

ゲストOSの時刻 = ESXiのシステムクロック + 仮想NVRAMの時刻差分?

血眼になって情報調査をすること数十分。

はてなブログでVMwareの時刻管理について言及している記事がヒット。
これがなかったら多分数時間は頭抱えてた。
それによると、以下のように書いてあった。

RTC TOD
擬似的なエミュレーションをおこないます。guest OS が「ハードウェア時刻」の取得を行う際，host OS の「時刻」に，ある種の「差分」を加減したものを返します。

このある種の「差分」は，通常状態であれば，VMware guest の nvram に保存されています。

たとえば，現在 nvram に「差分」が +3min として保存されているとします。

現在の host OS の「時刻」が 09:00:00 とする

guest OS で「ハードウェア時刻」を取得すると，09:03:00 が返る

のようになります。

また，たとえば

現在の host OS の「時刻」が 12:00:00 とする

guest OS で「ハードウェア時刻」を 15:15:00 を設定する

guest OS の nvram の「差分」に +195min が設定される

のようになります。

nvramというのは、この場合ゲストOSの仮想NVRAMのことを指している。
VMの構成ファイルの一つだ。
で、そのファイルにESXiのシステムクロックとの差分を書き込んでいる・・・と。
これは物理ハードウェアと違ってESXiの場合、ゲストOSのハードウェアクロック = ESXiのシステムクロックであるからだろう。
通常とは違い左右されやすい情報であるがために、一々差分を取得し正確性を保とうとしているのではないか。と思う。

・・・ということはつまり、~~ゲストOSは自身のハードウェアクロックを取得する時~~ ESXiはゲストOSのハードウェアクロックを処理して表示させる時、ESXiのシステムクロックだけでなく、仮想NVRAMに保存されている差分時刻も計算しているのではないだろうか?
(2016/03/31) 上記を一部修正しました。

そう考えれば辻褄が合うのだ。
下にフローを書き出してみる。

ESXiのシステムクロックは11分遅れていた。
その状態でゲストOSの時刻を合わせたところ、仮想NVRAMファイルに差分として +11分 が書き込まれた。
ESXiにNTPサーバを設定したが更新されなかったため、ESXiのシステムクロックを手動で合わせた(この時 +11分 したことになる)。
ゲストOSではWindows Time サービスが停止しているため、システムクロックをハードウェアクロックに合わせに行こうとする。これまではESXi側で ESXiのシステムクロック + 仮想NVRAMファイルの差分(+11分) という処理をしていたため、ゲストOSがその情報をハードウェアクロックとして読み取り、システムクロックに反映させていた。そのため、11分の差分が埋まりゲストOSのシステムクロックは正常に動作しているように見えた。しかし、ESXiのシステムクロックを手動で合わせたところ、ゲストOSのシステムクロックが狂った。
ESXiのシステムクロック自体は正常な値に戻ったが、仮想NVRAMには +11分という値が格納されている。 この 正常な値のESXiのシステムクロック + 仮想NVRAMファイルの差分(+11分) というのをESXi側が処理してゲストOSに見せており、それをゲストOSがシステムクロックとして合わせてしまったために時刻が11分進んでしまったのでは?

書いてたらよくわからないことになってしまった。
SCやらHCやらウザいんじゃ！！！

上のフローはただの自分の推測なのだが。
でもこうとしか思えない。ていうかこれだろ。これであれ。

・・・もうこの線で行くか。
これ以上はドキュメントもないしわかんない。
という事でこれをゴリ推した。

ともあれ、それから時刻のずれは起きていない。
多分これで良かったんだろうと、そう思っている。

再発したらもうわからん。

とりあえず、めでたし。

※
まとめは書こうと思ったけど、めんどくさくなって止めた。
とりあえず全体的にグダグダが過ぎる。自分の文章力を呪う。
後で修正掛けるつもりです。表記ゆれとか酷いので。

ESXi上のWindowsゲストの時刻がずれて詰みかけた話

事象