前回

先日 の続き。

なんとか O 7.4 の環境も作ったけどこっちも failed to ping storm 状態が再現しないのでもう解決したもんだと思われてそうなんやな、まぁエラーが起きなければ例外処理コードが間違ってても発覚しないのは人生と同じである。

RPCI 側のデバッグ(わからん)

前回の推測はてんでハズレ、サスペンドからの復帰時に RPCI は TCLO のリセット通知を待つ必要はなく全く無関係という結論。

というか N54L では発生せず C2D T7500 で発生するという環境問題だったようで、チェンジしたらオレオレ N6 でも発生するわこれ。

エラーメッセージのこの部分。

Feb  1 18:22:43 hellbent /netbsd: [  44.0526304] vmware: get data failed, ebx=0x100000

842 static int
843 vm_rpc_get_data(const struct vm_rpc *rpc, char *data, uint32_t length,
844     uint16_t dataid)
845 {
846 	struct vm_backdoor frame;
847 
848 	/* Get data using enhanced RPC. */
849 	memset(&frame, 0, sizeof(frame));
850 	frame.eax = VM_MAGIC;
851 	frame.ebx = VM_RPC_ENH_DATA;
852 	frame.ecx = length;
853 	frame.edx = VM_REG_PORT_RPC(rpc->channel);
854 	frame.esi = rpc->cookie1;
855 	frame.edi = (register_t)data;
856 	frame.ebp = rpc->cookie2;
857 
858 	vm_ins(&frame);
859 
860 	/* NUL-terminate the data */
861 	data[length] = '\0';
862 
863 	if (__SHIFTOUT(frame.ebx, VM_REG_WORD_MASK) != VM_RPC_ENH_DATA) {
864 		printf("vmware: get data failed, ebx=%#"PRIxREGISTER"\n",
865 		    frame.ebx);
866 		return EIO;
867 	}

79 #define VM_RPC_ENH_DATA		0x00010000UL /* with enhanced RPC data calls. */

ここ vm_ins() の後 ebx レジスタに入ってる値って元からは変更されず 0x100000 ではなく 0x10000 のはずなんだよね。

そもそも何の通信に失敗してるのか

ここで失敗してる通信の内容は vmt_tclo_state_change_success() を使ってホストからのサスペンドボタン押されたよ通知に対して、ゲスト OS 側でサスペンドの準備できたよと返すところ。

Feb  1 18:22:43 hellbent /netbsd: [  44.0526304] vmt0: unable to send state change result

608 	} else if (strcmp(sc->sc_rpc_buf, "OS_Suspend") == 0) {
609 		log(LOG_KERN | LOG_NOTICE, "VMware guest entering suspended state\n");
610 
611 		vmt_tclo_state_change_success(sc, 1, VM_STATE_CHANGE_SUSPEND);

440 static void
441 vmt_tclo_state_change_success(struct vmt_softc *sc, int success, char state)
442 {
443 	if (vm_rpc_send_rpci_tx(sc, "tools.os.statechange.status %d %d",
444 	    success, state) != 0) {
445 		device_printf(sc->sc_dev, "unable to send state change result\n");
446 		sc->sc_rpc_error = 1;
447 	}
448 }

93 /* VM state change IDs */
94 #define VM_STATE_CHANGE_HALT	1
95 #define VM_STATE_CHANGE_REBOOT	2
96 #define VM_STATE_CHANGE_POWERON 3
97 #define VM_STATE_CHANGE_RESUME  4
98 #define VM_STATE_CHANGE_SUSPEND 5

とはいっても *BSD は ACPI 2.0 から 1/4 世紀経過した現在でも S4 Sleep が実装されてないし、そもそも VMware では APM 時代の電源管理のように仮想マシン側で勝手にハイバネートするからやるべきこともできることも何もないのだ。 ゲストとしてはあたかも時間停止の魔法をかけられたようなもんである。

というかちょっと待て、何か変だな札幌ドーム。

これ TCLO 側の OS_Suspend イベントはあくまでボタンが押されたよ通知であって、RPCI 側からサスペンドの準備できたよを返さないと VMware 側はハイバネ実行しないはずなのだ。

なので寝たってことはホスト側は vmt_tclo_state_change_success(1, VM_STATE_CHANGE_SUSPEND) は成功だがゲストからはレジスタの値がおかしいってことになるのかぁ。

もしかして vm_ins() 叩いた次の瞬間にすでにゲスト OS の時間は凍ってたりすると、これらのレジスタ値を確認する頃にはとっくにサスペンドから復帰してる可能性あるんだよな、時刻同期されるのが OS_Resume　イベント受けとってからだからログみただけだと連続してるようにみえるんだけどね。

Feb  2 11:34:27 tycho /netbsd: VMware guest entering suspended state

実はもうここの直後に眠ってて

Feb  2 11:34:27 tycho /netbsd: vmware: get data failed, ebx=0x100000
Feb  2 11:34:27 tycho /netbsd: vmt0: failed to get rpci response data
Feb  2 11:34:27 tycho /netbsd: vmt0: unable to send state change result
Feb  2 11:34:27 tycho /netbsd: vmt0: resetting rpc
Feb  2 13:42:10 tycho /netbsd: vmt0: guest resuming from suspended state

ここからは再開後の出力だったりしそうでなぁ。

じっさい寝てるゲスト OS の仮想ディスクを別でマウントして /var/log/message ひっぱりだすと出力されてないのよね。

といってもタイミング次第でまだメッセージはバッファ上なだけの可能性もあるしデバッガでも無けりゃ本当のところ判らんので判断は保留。

次回

解決まで時間かかりそうなので別のお話しようかね。 オレオレ N6 で修正した(および今後改善したい)時刻同期周りの実装の解説をしようかと。

若干ネタバラシすると、今の実装は VMware 側で時刻の同期を「する/しない」のチェックボックスを設定してても値を見ておらず、問答無用で時刻同期してしまうというひどいコードなのだ。