BitVisor上でオペレーティングシステムが正しく起動しないなどの問題が発生した時、オペレーティングシステム側の機能でダンプなどが取れれば良いのですが、うまくいかないこともあります。そういう時は、オペレーティングシステムで発生した例外と、例外の原因となった命令を調べると新たな発見があることがあります。例えば、BitVisorが対応していない新しい命令が使われていて、無効命令例外が発生している場合があります。

BitVisorが使用しているIntel VT-xやAMD-Vでは、仮想マシン上で発生した例外を追うことができます。

BitVisorの仮想マシン上で発生した例外を追う方法

Intel VT-xの場合

VT-xの初期の (Unrestricted Guestが登場する前の) 実装では、仮想マシンをリアルアドレスモードにすることができなかったため、BitVisorでは仮想8086モードを利用してリアルアドレスモードのプログラムを実行していました。その関係で一部例外処理が複雑になっています。

どの例外でVM Exitするかを決めるexception bitmapというのがあって、BitVisorではこれを状況に合わせて変更していくようになっています。その変更を行うのがcore/vt_main.cのvt_update_exception_bmp()関数です。最近のCPUであればEPTとUnrestricted Guestに対応していますので、VM Exitの対象となる例外はNMIのみになっているはずです。古いCPUでは、動作モードの変更に応じて更新されるようになっています。

例外を追い掛けるには、まずここを変えます。0xFFFFFFFFにするとすべての例外でVM Exitするようになりますが、EPT対応のCPUの場合ページフォールト例外のところでpanicしてしまいますので、その場合は0xFFFFBFFFとしてページフォールトを対象外にするか、あるいは、core/vt_main.cのdo_exception()関数内のEXCEPTION_PFとの比較のところが成り立たないように書き換えましょう。

次に、例外の情報がBitVisorのログに残るようにします。core/vt_main.cのdo_exception()関数で例外の情報を取得しますので、そのへんにprintfを仕込むことでログに残すことができます。

AMD-Vの場合

AMD-Vは初期のものでも仮想マシンをリアルアドレスモードにすることができたため、例外まわりはIntel VT-xと比べてかなり簡単です。core/svm_init.cのsvm_vmcb_init()関数で、intercept_exceptionというのに0x4000と設定していますが、これがページフォールトの例外だけをinterceptするという意味です。core/svm_paging.cのsvm_paging_init()関数で、ページフォールトのinterceptが不要な場合は0x4000のビットを落としています。

例外を追い掛けるには、intercept_exceptionを最初から0xFFFFFFFFに設定します。ページフォールトのビットについては上述のようにクリアされる場合がありますので、ページフォールトも追いかけたい場合は注意してください。

後はsvm_exit_code()関数のswitch文で、VMEXIT_EXCP14だけがありますので、残りのVMEXIT_EXCP0〜31を作ります。例外の情報をログに残した上で、event injectionでゲストOSの例外ハンドラーが呼び出されるようにします。Event injectionの方法はcore/svm.cのsvm_generate_pagefault()関数を参考にしてください。

何をログに残すか

例外の番号の他に、%cs, %ripや実行しようとしていた機械語などを出力するようにすると良いです。時刻 (get_time()関数の返り値) も出すと良いこともあるかも知れません。

実装例

例として、iMac Mid-2014環境でページフォールト以外の例外を100個ログに出力する実装を差分で示します。(タブがスペースになっていますので試す時にはご注意ください。)

diff --git a/core/vt_main.c b/core/vt_main.c
--- a/core/vt_main.c
+++ b/core/vt_main.c
@@ -159,6 +159,7 @@ vt_update_exception_bmp (void)
                if (current->u.vt.handle_pagefault)
                        newbmp |= 1 << EXCEPTION_PF;
        }
+       newbmp |= ~(1 << EXCEPTION_PF); /* Debug */
        asm_vmwrite (VMCS_EXCEPTION_BMP, newbmp);
 }
 
@@ -222,6 +223,28 @@ do_exception (void)
 
        asm_vmread (VMCS_VMEXIT_INTR_INFO, &vii.v);
        if (vii.s.valid == INTR_INFO_VALID_VALID) {
+               static int count = 100;
+               u16 cs;
+               ulong cs_base;
+               ulong rip;
+               u8 code[8];
+               int i, codelen;
+               if (count < 0)
+                       goto skip;
+               count--;
+               current->vmctl.read_sreg_sel (SREG_CS, &cs);
+               current->vmctl.read_sreg_base (SREG_CS, &cs_base);
+               current->vmctl.read_ip (&rip);
+               for (codelen = 0; codelen < sizeof code; codelen++)
+                       if (read_linearaddr_b (cs_base + rip + codelen,
+                                              &code[codelen]))
+                               break;
+               printf ("Exception %u @ %04X:%08lX\n", vii.s.vector, cs, rip);
+               printf ("Code:");
+               for (i = 0; i < codelen; i++)
+                       printf (" %02X", code[i]);
+               printf ("\n");
+       skip:
                switch (vii.s.type) {
                case INTR_INFO_TYPE_HARD_EXCEPTION:
                        STATUS_UPDATE (asm_lock_incl (&stat_hwexcnt));

実際にUbuntu 16.04を起動して残ったログを以下に示します。100個も出ませんでした。

Exception 13 @ 0010:FFFFFFFF81064486
Code: 0F 32 45 31 C0 48 C1 E2
Exception 13 @ 0010:FFFFFFFF81064486
Code: 0F 32 45 31 C0 48 C1 E2
Exception 13 @ 0010:FFFFFFFF81064486
Code: 0F 32 45 31 C0 48 C1 E2
Exception 13 @ 0010:FFFFFFFF81064486
Code: 0F 32 45 31 C0 48 C1 E2
Exception 13 @ 0010:FFFFFFFF81064486
Code: 0F 32 45 31 C0 48 C1 E2
Exception 2 @ 0033:7F133DA6BE30
Code: 41 55 41 54 41 89 CD 55
Exception 2 @ 0010:FFFFFFFFC06A9DEB
Code: 5D C3 0F 1F 00 0F 1F 44

ここでは最初に数回の一般保護例外 (13) が記録されています。出力された機械語を見てわかる方も多いとは思いますが、一応objdumpコマンドを用いて命令を調べてみましょう。%ripの値が大きいので64ビットのようですから、-m i386:x86-64を指定します。

$ printf '\x0F\x32\x45\x31\xC0\x48\xC1\xE2' > a
$ objdump -D -b binary -m i386:x86-64 a

a:     file format binary


Disassembly of section .data:

0000000000000000 <.data>:
   0:	0f 32                	rdmsr  
   2:	45 31 c0             	xor    %r8d,%r8d
   5:	48                   	rex.W
   6:	c1                   	.byte 0xc1
   7:	e2                   	.byte 0xe2

このように、rdmsr命令であることがわかります。今回はここで問題が発生しているわけではありませんが、何か問題がある場合は、こうして命令がわかると、次にrdmsr命令が使うレジスターの内容をログに残してみるなどして、デバッグを進めていくことができます。