12年放置されていた vmt(4) のバグを追いかける
vmt(4) とは何か
vmt(4) は O で実装された in-kernel vmware-tools で N にも移植されている。
去年さくらの VPS を解約したことでオレオレ N6 の開発環境はまた VMware 上に戻りまたこいつとお付き合いすることになったのだ。
ところが vmt(4) ってやつは昔から不安定で、何かのタイミングで発狂し大量のエラーメッセージを吐くのだ。 特に先月末にホストを AMD-V に移動したところ、起動して10分も経つと100%再現するという状態に。
Jan 25 10:44:17 tycho /netbsd: vmware: sending length failed, eax=00000000, ecx=00000000
Jan 25 10:44:17 tycho /netbsd: vmt0: failed to send TCLO outgoing ping
Jan 25 10:44:17 tycho /netbsd: vmt0: resetting rpc
Jan 25 10:44:17 tycho /netbsd: vmware: sending length failed, eax=00000000, ecx=00000000
Jan 25 10:44:17 tycho /netbsd: vmt0: failed to send TCLO outgoing ping
Jan 25 10:44:17 tycho /netbsd: vmt0: resetting rpc
…
この問題は O で実装された12年前から 発生 していて N でもずいぶんと遅れて 2018 年に PR/53797 で報告されてるけれども今日にいたるまで未解決の問題である。
そもそも今となっては本家の VMware 社が vmware-tools を open-vm-tools としてオープンソース化してるし。 それなら vmt(4) は無効にして open-vm-tools 使うわって人も多いから誰ももう vmt(4) には興味ないのである。
ただ open-vm-tools には GLib/GTK+ がビルドに必要で、X Window System なんてもうここ10年インストールしてないミニマリスト的には vmt(4) の方がありがたいのだ。
デバッグ(そして即解決)
使ってる人間が自分以外にいないなら自分で直すしかないと観念しコードを読んだ、これ vm_rpc_close() を呼ぶタイミングが間違ってんだな。
- RPC の呼出に失敗したらそのポートは死んでるから vm_rpc_close() 呼んでいちどポートを閉じて再度 vm_rpc_open() からやり直す必要がある
- ところがコードは vm_rpc_close() でポートを閉じるのはホストからリセットイベントが飛んできた時と勘違いしてる
- その結果リセットイベントをポーリングする前に、死んだポート相手にPingを打とうとしエラーにエラーを重ねる
- さらに vm_rpc_open() した後、リセットイベントですでに投げたリセット受領通知を重複して投げて拒絶されるというオチまである
ということ。
いやまぁそれにしても kernel デバッグは何度もマシンの再起動が必要なるからマジでめんどい。
かつてのワイのワークエリア libc デバッグなんて最低限 LD_PRELOAD すりゃクラッシュしないかは判断できるからホンマ楽ですわ。 こんなの趣味にしてる人はマゾに違いない。
O HEAD 向けのパッチ
パッチ(patch-obsd-vmt-bugfix.txt)は ここ置いた 、ただし O 7.4 がインストール中にクラッシュするのでビルドも動作も確認してないので注意。
diff --git a/sys/dev/pv/vmt.c b/sys/dev/pv/vmt.c
index 824d8530dbd..e0a4e30d295 100644
--- a/sys/dev/pv/vmt.c
+++ b/sys/dev/pv/vmt.c
@@ -273,6 +273,7 @@ void vm_outs(struct vm_backdoor *);
/* Functions for communicating with the VM Host. */
int vm_rpc_open(struct vm_rpc *, uint32_t);
int vm_rpc_close(struct vm_rpc *);
+int vm_rpc_alive(const struct vm_rpc *);
int vm_rpc_send(const struct vm_rpc *, const uint8_t *, uint32_t);
int vm_rpc_send_str(const struct vm_rpc *, const uint8_t *);
int vm_rpc_get_length(const struct vm_rpc *, uint32_t *, uint16_t *);
@@ -447,11 +448,7 @@ vmt_attach(struct device *parent, struct device *self, void *aux)
return;
}
- if (vm_rpc_open(&sc->sc_tclo_rpc, VM_RPC_OPEN_TCLO) != 0) {
- printf("%s: failed to open backdoor RPC channel "
- "(TCLO protocol)\n", DEVNAME(sc));
- goto free;
- }
+ bzero(&sc->sc_tclo_rpc, sizeof(sc->sc_tclo_rpc));
/* don't know if this is important at all yet */
if (vm_rpc_send_rpci_tx(sc,
@@ -763,21 +760,13 @@ vmt_shutdown(void *arg)
DPRINTF("%s: failed to send shutdown ping\n", DEVNAME(sc));
}
- vm_rpc_close(&sc->sc_tclo_rpc);
+ if (vm_rpc_alive(&sc->sc_tclo_rpc))
+ vm_rpc_close(&sc->sc_tclo_rpc);
}
void
vmt_tclo_reset(struct vmt_softc *sc)
{
- if (sc->sc_rpc_error != 0) {
- DPRINTF("%s: resetting rpc\n", DEVNAME(sc));
- vm_rpc_close(&sc->sc_tclo_rpc);
-
- /* reopen and send the reset reply next time around */
- sc->sc_rpc_error = 1;
- return;
- }
-
if (vm_rpc_send_str(&sc->sc_tclo_rpc, VM_RPC_RESET_REPLY) != 0) {
DPRINTF("%s: failed to send reset reply\n", DEVNAME(sc));
sc->sc_rpc_error = 1;
@@ -1111,26 +1100,16 @@ vmt_tclo_tick(void *xarg)
VM_BACKUP_SUCCESS, "");
}
- /* reopen tclo channel if it's currently closed */
- if (sc->sc_tclo_rpc.channel == 0 &&
- sc->sc_tclo_rpc.cookie1 == 0 &&
- sc->sc_tclo_rpc.cookie2 == 0) {
+ /* open tclo channel if it's currently closed */
+ if (!vm_rpc_alive(&sc->sc_tclo_rpc)) {
if (vm_rpc_open(&sc->sc_tclo_rpc, VM_RPC_OPEN_TCLO) != 0) {
- DPRINTF("%s: unable to reopen TCLO channel\n",
- DEVNAME(sc));
+ DPRINTF("%s: failed to open backdoor RPC channel "
+ "(TCLO protocol)\n", DEVNAME(sc));
delay = 15;
goto out;
}
-
- if (vm_rpc_send_str(&sc->sc_tclo_rpc,
- VM_RPC_RESET_REPLY) != 0) {
- DPRINTF("%s: failed to send reset reply\n",
- DEVNAME(sc));
- sc->sc_rpc_error = 1;
- goto out;
- } else {
- sc->sc_rpc_error = 0;
- }
+ sc->sc_rpc_error = 0;
+ sc->sc_tclo_ping = 1;
}
if (sc->sc_tclo_ping) {
@@ -1176,12 +1155,16 @@ vmt_tclo_tick(void *xarg)
}
}
+out:
if (sc->sc_rpc_error == 1) {
+ DPRINTF("%s: resetting rpc\n", DEVNAME(sc));
+ vm_rpc_close(&sc->sc_tclo_rpc);
+ /* reopen and send the reset reply next time around */
+
/* On error, give time to recover and wait a second */
delay = 1;
}
-out:
timeout_add_sec(&sc->sc_tclo_tick, delay);
}
@@ -1533,6 +1516,12 @@ vm_rpc_close(struct vm_rpc *rpc)
return 0;
}
+int
+vm_rpc_alive(const struct vm_rpc *rpc)
+{
+ return rpc->channel != 0 || rpc->cookie1 != 0 || rpc->cookie2 != 0;
+}
+
int
vm_rpc_send(const struct vm_rpc *rpc, const uint8_t *buf, uint32_t length)
{
上で説明した通りのパッチすね。
N HEAD 向けのパッチ
同じ場所に置いたパッチ(patch-nbsd-vmt-bugfix.txt)適用すれば解決するはず、 こっちはビルドと起動は確認。
ところがオレオレ N6 でド不安定だった AMD-V 環境でも N HEAD はパッチ適用せず安定して動いてるっぽいんだよね。
うーん？ RPC が不安定になるのは vmt(4) とは別に問題あって N HEAD ではそれが解決してるから当該箇所まで到達していない？
もういっちょバグのようなものを発見
そして代わりに N HEAD だと別のバグが露見するもよう。
Jan 31 02:17:41 hellbent /netbsd: [ 116066.6810491] vmware: get data failed, ebx=0x100000
Jan 31 02:17:41 hellbent /netbsd: [ 116066.6810491] vmt0: failed to get rpci response data
Jan 31 02:17:41 hellbent /netbsd: [ 116066.6810491] vmt0: unable to send state change result
Jan 31 02:17:41 hellbent /netbsd: [ 116066.6923936] vmt0: resetting rpc
...
Jan 31 15:22:55 hellbent /netbsd: [ 151875.8526499] vmt0: failed to get rpci response data
Jan 31 15:22:55 hellbent /netbsd: [ 151875.8526499] vmt0: unable to send state change result
Jan 31 15:22:55 hellbent /netbsd: [ 151875.9070062] vmt0: resetting rpc
Jan 31 15:22:55 hellbent /netbsd: [ 151876.2525367] vmt0: guest resuming from suspended state
別の vm_rpc_open() で取得した接続でのデータ交換が失敗してますわねこれ。
VMware のバックドアにまつわる簡単な説明
バックドアには
- コマンド … 0x5658
- RPC(リモートプロシージャコール) … 0x5659
の二種類がある、やってることは x86 なら eax にマジックナンバー(0x564D5868)置いて inl するなんだけどね。
ただコマンドは非常に効率が悪い、どの CPU であっても一度に x86 のレジスタサイズを超えない4バイトまでしかデータ交換ができない。 なので今となっては自分がゲスト OS なのかを知るためにバージョン情報を入れ叩くくらいしか使わないのだ。
そんで RPC の方はレジスタにバッファへのポインタアドレス置いてやりとりするから一度に大量のデータ交換ができる。
ただしまずは送受信するデータの長さをコマンドで通知した後に、改めて送受信のために x86 なら insb/outsb するので煩雑ではある。 とうぜん atomic でもないけどそんなもん必要な操作は無いからまぁいいか。
さらに RPC にもチャンネルが2つあって
- TCLO(0x49435052) … ホストからゲストへのシャットダウンなどのイベント通知
- RPCI(0x4F4C4354) … ゲストからホストへホスト名やIPアドレス情報などの情報通知、すべてテキストベース
の二種類がある。
今回書いたパッチでは TCLO 側のバグを潰したのだけど、今度は RPCI 側の方なんやな。
そもそも TCLO はポート開きっぱなしにしてタイマーで定期的に Ping を打ちながらイベントがキューに溜まるのをポーリングするドモホルンリンクル型。
しかし RPCI は通信のたびに毎度ポートをオープンしてクローズするワンキル型だから延々と失敗が続くことにならないのだ。
もしかすると TCLO 側でリセットイベントが飛んでくるまでは RPCI 側は送信禁止にする必要があるのかなこれ。
そうすると オレオレ N6 で発生しないのはタイマーである callout(9) 周りの実装が変わっててタイミングが変わったとかそういう感じだろうか。
次回
次は RPCI 側のバグを潰そうかと、あとバグフィックス以外にもオレオレN6では vmt(4) 周り大きくイジってるのでそのあたりのお話でも。