この記事は自作OS Advent Calendar 2022の17日目の記事です。他の記事も是非お楽しみください！（そして書ける方はぜひ参加してみてください！！）

前回(?)までのあらすじ

hikaliumは自作OS上で動くアプリからsyscall命令を使ってシステムコールを呼べるようにしようと頑張っていたが、なぜか発生するトリプルフォルトによりQEMUが再起動してしまい、3時間のデバッグの末力尽きてしまった。一体なぜ例外が発生するのか、その謎を解くため、我々は数日の休息をとったのち、バイナリの森へと旅立った…。

前回（という名の配信アーカイブ）:

www.youtube.com

状況を整理しよう

バイナリの森は危険だ。無闇に動きまわっては、x86の沼に足をとられて命を落としかねない。まずは我々の向かっていた先と、これまでに得た情報をまとめることにしよう。

どこへ向かっていたのか

我々のひとまずの目標は、自作OS上で実行されるアプリケーションから、Rustのprintln!()マクロを介して文字列を出力することであった。Rustはとてもよくできていて、coreクレートの中に、C言語でいうsprintfに相当する、fmtモジュールが存在しており、既存のOSの支援が期待できないno_std環境でも変数の中身などを容易にかつ美しく表示する関数およびマクロを容易に実装することができる。そう、我々はもう闇のようなlibc++やnewlibに頼らなくてもよくなったのだ。10年前のように、自前でsnprintfもどきを実装するまでもない。世界は日増しによくなりつつある。

ではprintln!マクロを実装するにあたり、自作OSが提供しなければならない機能は一体何かというと、それは「文字列を表示する」という機能である。というのも、coreクレートにはOSに依存するような機能は含められないため、「文字を画面に出す」などといった、物理世界とのインタラクション、つまりはハードウエアの制御などのOSが支配している領域の操作はcoreクレートの外で自前で用意してやらなければならない。core::fmtは、フォーマット文字列と引数をもとに、メモリ上に「表示するべき文字列」を生成してはくれるが、それを表示するのは我々の責務なのだ。

というわけで、我々はprint_stringというシステムコールを用意した。これは、メモリ上に存在する文字列へのポインタと、文字列の長さを指定すると、OSがそれを画面上に表示してくれる、というものである。実は、このシステムコール自体はどうも動作しているようで、実際にアプリケーションからprint_stringシステムコールを介して固定の文字列を出力してみた場合は、想定通りに文字列が出力されていたことが確認できている。

それならば、あとはprint_stringに対して、core::fmtによって生成された文字列を渡してあげればよいのではないか、我々はそう踏んでいたのだ。

なにがあったのか

…しかし、その考えはあまりにも浅はかだった。実際に、以下のようにprint_stringを置き換えてみたところ、なんとOSが再起動してしまったのだ。

#![no_std]
#![no_main]

use noli::*;

fn main() -> i64 {
    //sys_print("hello!");
    println!("{}", 42);
    return -42;
}

entry_point!(main);

どうも、何らかの理由でCPUの例外が発生し、トリプルフォルトに至って再起動してしまう、というところまではわかったのだが、我々はそこで一旦力尽きてしまったのだった…。

まずは何が起きているのかを理解しよう

現状は先ほど伝えた通りだ。次は、我々がどちらに向かえばよいのか、それを考えることにしよう。そのためには、我々がいま直面している現象を正しく理解することが必要不可欠だ。まずは、具体的にどのような例外でトリプルフォルトに至っているのか、それを確認することにしよう。

QEMUには、例外が発生した際にログを出力する機能が存在している。これはデフォルトでオフになっているが、-d というフラグを介して制御することが可能だ。

$ qemu-system-x86_64 -d ?
Log items (comma separated):
out_asm         show generated host assembly code for each compiled TB
in_asm          show target assembly code for each compiled TB
op              show micro ops for each compiled TB
op_opt          show micro ops after optimization
op_ind          show micro ops before indirect lowering
int             show interrupts/exceptions in short format
exec            show trace before each executed TB (lots of logs)
cpu             show CPU registers before entering a TB (lots of logs)
fpu             include FPU registers in the 'cpu' logging
mmu             log MMU-related activities
pcall           x86 only: show protected mode far calls/returns/exceptions
cpu_reset       show CPU state before CPU resets
unimp           log unimplemented functionality
guest_errors    log when the guest OS does something invalid (eg accessing a
non-existent register)
page            dump pages at beginning of user mode emulation
nochain         do not chain compiled TBs so that "exec" and "cpu" show
complete traces
plugin          output from TCG plugins

strace          log every user-mode syscall, its input, and its result
tid             open a separate log file per thread; filename must contain '%d'
trace:PATTERN   enable trace events

Use "-d trace:help" to get a list of trace events.

おっと、言い忘れていたが、我々は以下のバージョンのQEMUを自前ビルドして利用している。一応伝えておこう。

$ qemu-system-x86_64 --version
QEMU emulator version 7.2.0 (v7.2.0-dirty)
Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers

さて、本筋に戻るとしようか。というわけで、以下のようなオプションをQEMUに追加すれば、例外に関するログが、カレントディレクトリの qemu_debug.log というファイルに出力されるはずである。（出力先のファイルは-Dオプションで指定している。）また、 --no-reboot をつけておくと、トリプルフォルトでCPUにリセットがかかった際に、再起動するのではなくQEMUを終了することができるようになる。再起動のループを楽しみたい気分であるなら話は別だが、これも設定しておくとデバッグが楽になるだろう。

-d int,cpu_reset -D qemu_debug.log --no-reboot

さて、これでもう一回自作OSを起動してみる。アプリは自動で起動するように設定してあるから、クラッシュしてすぐQEMUが落ちるはずだ。

…予想通り落ちた。ログを確認しよう。

$ cat qemu_debug.log | grep -A 1 -e check_exception -e Triple
check_exception old: 0xffffffff new 0xe
   159: v=0e e=0000 i=0 cpl=0 IP=0008:0000000000200fd0 pc=0000000000200fd0 SP=0010:000000003e286be0 CR2=0000002000000000
--
check_exception old: 0xffffffff new 0xd
   160: v=0d e=0000 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003e286928 env->regs[R_EAX]=0000002000000000
--
check_exception old: 0xffffffff new 0xd
   161: v=0d e=0000 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003e286668 env->regs[R_EAX]=0000002000000000
--
...
--
check_exception old: 0xffffffff new 0xd
  6458: v=0d e=0000 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003de4c1a8 env->regs[R_EAX]=0000002000000000
--
check_exception old: 0xffffffff new 0xd
  6459: v=0d e=0000 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003de4bee8 env->regs[R_EAX]=0000002000000000
--
check_exception old: 0xd new 0xe
  6460: v=0e e=0002 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003de4bee8 CR2=000000003de4bed8
--
check_exception old: 0xe new 0xe
  6461: v=08 e=0000 i=0 cpl=0 IP=0008:000000003e290f91 pc=000000003e290f91 SP=0010:000000003de4bee8 env->regs[R_EAX]=0000002000000000
--
check_exception old: 0x8 new 0xe
Triple fault

おお、結構な量のログが出ている。はて、一体何が起きているのだろうか…。

例外コードを順に追っていくと、以下のような流れで例外が起きていることがわかる。

ページフォルト(0xe)が0x200fd0の命令を実行中に発生した。ページフォルトの要因となったアドレスは CR2=0x2000000000 である。
一般保護例外(0xd)が0x3e290f91の命令を実行中に発生した。
同じ例外が次々と発生し、スタックポインタが0x3e286928から0x3de4bee8まで変化した。
最終的に、スタックポインタと同じアドレスであるCR2=0x3de4bed8 にアクセスしようとして、再度ページフォルト(0xe)が発生した。
ここでさらにページフォルト(0xe)が発生し、これによってダブルフォルト(0x8)が発生した。
ダブルフォルト(0x8)の発生中にさらにページフォルト(0xe)が発生し、最終的にトリプルフォルトとなってリセットがかかった。

つまるところ、

最初のきっかけは、0x200fd0の命令がアドレス0x2000000000にアクセスしようとしてページフォルト(0xe)を発生させたことにある。
そのページフォルトを処理している最中に一般保護例外(0xd)が発生し、一般保護例外を処理中にもさらに一般保護例外が発生することで、順次スタックが食い潰されていった。
例外ハンドラのスタックが枯渇し、0x3de4bed8にアクセスしようとした段階でページフォルトが発生した。これにより、ダブルフォルトが発生した。
ダブルフォルトハンドラも同一のスタックを使用していたため、再度ページフォルトが発生し、トリプルフォルトとなってリセットがかかった。

ということのようだ。 …例外を正しく処理できないOSでごめんなさい…（仕方ないよ、完璧なOSなんて存在しないもの。直していきましょう！）

さて、ここらへんで日付変更線が近づいてきたようだ。続きはまた明日…（睡眠は大事ですよ！おやすみなさい！）