- MikanOS のリポジトリ https://github.com/uchan-nos/mikanos
- 現象を確認したコミット b08a21e5d6b65f870da55e2bd1430762c0025ac2
- このコミットは uchan のローカルマシンにしか存在しない可能性がある
QEMU にて MikanOS を起動させ，初期ターミナルにて「rpn 2 3 +」と入力しエンター。 画面に「app exited. ret = 5」と表示された後，いずれかのキーを入力すると MikanOS が再起動される（ブートローダーの処理からまた開始される）。
次の 3 つのいずれかを行うと現象が治まる。（それぞれ，現象を治めるのに最小の変更かどうかは検証していない）
- GDT に TSS を設定し，ltr する
- 標準例外に対応するハンドラを作り IDT にセットする
- Task::InitContext 内で Log() を使ってログを出す
- RSP0，IST1 にそれぞれ 8KiB のスタック領域を設定した TSS を作成。
- GDT[5]（および GDT[6]） に TSS を設定。
- ltr で TR=5 をロード。
そもそも，このコミットの時点では，rpn コマンドはカーネルモード（CPL=0）で動く。
ターミナル内で rpn の ELF ファイルをロードし，エントリポイントを call 命令で呼び出すだけの簡単な仕組み。
CPL=0 以外で動くコンテキストは存在しないので，タイマー割り込みなどの割り込み発生時に CPL=3 → CPL=0 への遷移が起きず，TSS.RSP0 は使われないはずである。 また，いずれの IDT entry でも IST=0 としているため，TSS.IST1 も使われないはず。
だから，TSS を GDT に登録したこと自体は論理的には影響を及ぼさないはずである。（が，何故か現象は治まる）
標準例外（DE, DB, BP, OF, BR, UD, NM, DF, TS, NP, SS, GP, PF, MF, AC, MC, XM, VE）に対応する割り込みハンドラを作り， それぞれの割り込みベクタに対応する IDT entry を設定する。
これらの割り込みハンドラは，割り込み発生時に積まれるスタックフレームの CS:RIP, RFLAGS, SS:RSP, オプションでエラーコードを 画面に表示した後，永久ループするハンドラとなっている。 いずれのハンドラも呼ばれないにも関わらず，現象は治まる。
タスク ID，Task::context_.rsp の値，Task::context_ のアドレスを画面に表示するだけのログ出力を Task::InitContext() に追加してみると，現象が治まる。
まず，Task::InitContext 内で Log() を使ってログを出すときと出さないときの差を見てみたい。 まず，ログから得られた情報は次の通り。
| TaskID | RSP の初期値 | ctx addr |
|---|---|---|
| 2 | 0x00fe8ad8 | 0x00fe77b0 |
| 3 | 0x00feae78 | 0x00fe9b70 |
タスク用スタックは 4KiB を確保しているので，スタック領域は
- Task2 が 0x00fe7ae0 - 0x00fe8ad8
- Task3 が 0x00fe9e80 - 0x00feae78
となっている（8 バイト程度の誤差はあるかも）。 このことは，Task クラスを割り当てた直後にスタック領域を割り当てていることとも整合している。
rpn コマンドが終了した直後（ターミナルが "app exited. ret = %d" を表示しようとする行）である terminal.cpp:267 にブレークポイントを仕掛けてコンテキストの中身を見てみる。
(gdb) p /x *(TaskContext*)0x00fe77b0
$1 = {cr3 = 0x250000, rip = 0x10ec0d, rflags = 0x6, reserved1 = 0x0, cs = 0x100008, ss = 0x10,
fs = 0x10e0000, gs = 0x0, rax = 0xf8, rbx = 0x0, rcx = 0x10e0c20, rdx = 0x1, rdi = 0xfe6450,
rsi = 0xfe77b0, rsp = 0xfe8950, rbp = 0xfe8aa0, r8 = 0x80000000, r9 = 0x10fae, r10 = 0x0,
r11 = 0x30, r12 = 0x0, r13 = 0x0, r14 = 0x0, r15 = 0x0, fxsave_area = {__elems_ = {
0x0 <repeats 28 times>, 0xff, 0xff, 0x0 <repeats 130 times>, 0xc7, 0x3,
0x0 <repeats 350 times>}}}
(gdb) p /x *(TaskContext*)0x00fe9b70
$3 = {cr3 = 0x250000, rip = 0x113ca8, rflags = 0x6, reserved1 = 0x0, cs = 0x110008, ss = 0xfe0010,
fs = 0x10d0000, gs = 0x0, rax = 0x1bd, rbx = 0xfe9b50, rcx = 0x10dcc00, rdx = 0x1,
rdi = 0xfe77b0, rsi = 0xfe9b70, rsp = 0xfeadb0, rbp = 0xfeadc0, r8 = 0xfebf30, r9 = 0x5e,
r10 = 0xfe9b50, r11 = 0xfc88c0, r12 = 0xfeadd0, r13 = 0xfeae08, r14 = 0xf00000007,
r15 = 0xfe9b50, fxsave_area = {__elems_ = {0x0 <repeats 28 times>, 0xff, 0xff,
0x0 <repeats 130 times>, 0xee, 0x2, 0x0 <repeats 350 times>}}}
RIP と RSP の値が重要なので抜き出してみると，RSP がちゃんとスタック領域に収まっており妥当な感じ。
| TaskID | RIP | RSP | スタック領域 |
|---|---|---|---|
| 2 | 0x0010ec0d | 0x00fe8950 | 0x00fe7ae0 - 0x00fe8ad8 |
| 3 | 0x00113ca8 | 0x00feadb0 | 0x00fe9e80 - 0x00feae78 |
次にログ出力している行をなくして実験。 次に示すように，2 つのタスクの Context 構造体のアドレスは，ログ出力があったときと完全に同じ。
Breakpoint 2 at 0x113b94: Task::InitContext. (2 locations)
(gdb) c
Continuing.
Breakpoint 2, TaskManager::TaskManager (this=0xfe6340) at task.cpp:75
75 .InitContext(TaskIdle, 0)
(gdb) p /x idle.id_
$3 = 0x2
(gdb) p /x &idle.context_
$2 = 0xfe77b0
(gdb) c
Continuing.
Breakpoint 2, Task::InitContext (this=0xfe9b50, f=0x11a4d0 <TaskTerminal(unsigned long, long)>,
data=0) at task.cpp:18
18 stack_.resize(stack_size);
(gdb) p /x id_
$4 = 0x3
(gdb) p /x &context_
$5 = 0xfe9b70
(gdb) c
Continuing.
この状態で rpn コマンド終了直後のコンテキストの値を見てみる。
(gdb) p /x *(TaskContext*)0x00fe77b0
$6 = {cr3 = 0x250000, rip = 0x10ec0d, rflags = 0x6, reserved1 = 0x0, cs = 0x100008, ss = 0x10,
fs = 0x10d0000, gs = 0x0, rax = 0xd6, rbx = 0x0, rcx = 0x10dfc10, rdx = 0x1, rdi = 0xfe6450,
rsi = 0xfe77b0, rsp = 0xfe8950, rbp = 0xfe8aa0, r8 = 0x7, r9 = 0x442a, r10 = 0x0,
r11 = 0x10dcbe0, r12 = 0x0, r13 = 0x0, r14 = 0x0, r15 = 0x0, fxsave_area = {__elems_ = {
0x0 <repeats 28 times>, 0xff, 0xff, 0x0 <repeats 130 times>, 0xff, 0x3,
0x0 <repeats 350 times>}}}
(gdb) p /x *(TaskContext*)0x00fe9b70
$7 = {cr3 = 0x250000, rip = 0x113c88, rflags = 0x6, reserved1 = 0x0, cs = 0x110008, ss = 0xfe0010,
fs = 0xfe0000, gs = 0x0, rax = 0x1fa, rbx = 0xfe9b50, rcx = 0xfe8af0, rdx = 0x1, rdi = 0xfe77b0,
rsi = 0xfe9b70, rsp = 0xfeadb0, rbp = 0xfeadc0, r8 = 0xfebf30, r9 = 0x5e, r10 = 0xfe9b50,
r11 = 0xfc88c0, r12 = 0xfeadd0, r13 = 0xfeae08, r14 = 0xf00000007, r15 = 0xfe9b50, fxsave_area = {
__elems_ = {0x0 <repeats 28 times>, 0xff, 0xff, 0x0 <repeats 130 times>, 0xcb, 0x2,
0x0 <repeats 350 times>}}}
| TaskID | RIP | RSP | スタック領域 |
|---|---|---|---|
| 2（ログ有り） | 0x0010ec0d | 0x00fe8950 | 0x00fe7ae0 - 0x00fe8ad8 |
| 2（ログ無し） | 0x0010ec0d | 0x00fe8950 | 0x00fe7ae0 - 0x00fe8ad8 |
| 3（ログ有り） | 0x00113ca8 | 0x00feadb0 | 0x00fe9e80 - 0x00feae78 |
| 3（ログ無し） | 0x00113c88 | 0x00feadb0 | 0x00fe9e80 - 0x00feae78 |
特に怪しそうなところがない。 この後 continue した後，rpn コマンドを実行しようとしてキー入力するとすぐに MikanOS が再起動する。
これだけだとよくわからんので 1 回目の rpn コマンドの実行後，2 回目のキー入力を開始する直前で止めて調査してみる。
^C
Program received signal SIGINT, Interrupt.
0x0000000000114531 in (anonymous namespace)::TaskIdle (task_id=2, data=0) at task.cpp:9
9 while (true) __asm__("hlt");
(gdb) i r
rax 0x0 0
rbx 0x0 0
rcx 0x0 0
rdx 0x0 0
rsi 0x0 0
rdi 0x2 2
rbp 0xfe8ad0 0xfe8ad0
rsp 0xfe8ad0 0xfe8ad0
r8 0x0 0
r9 0x0 0
r10 0x0 0
r11 0x0 0
r12 0x0 0
r13 0x0 0
r14 0x0 0
r15 0x0 0
rip 0x114531 0x114531 <(anonymous namespace)::TaskIdle(unsigned long, long)+17>
eflags 0x202 [ IF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
(gdb) p /x *(TaskContext*)0x00fe77b0
$1 = {cr3 = 0x250000, rip = 0x10ec0d, rflags = 0x6, reserved1 = 0x0, cs = 0x100008, ss = 0x10,
fs = 0xfe0000, gs = 0x0, rax = 0xb6, rbx = 0x0, rcx = 0xfe8af0, rdx = 0x1, rdi = 0xfe77b0,
rsi = 0xfe77b0, rsp = 0xfe8950, rbp = 0xfe8aa0, r8 = 0x80000000, r9 = 0x992, r10 = 0x0,
r11 = 0x30, r12 = 0x0, r13 = 0x0, r14 = 0x0, r15 = 0x0, fxsave_area = {__elems_ = {
0x0 <repeats 28 times>, 0xff, 0xff, 0x0 <repeats 130 times>, 0xb6, 0x2,
0x0 <repeats 350 times>}}}
(gdb) p /x *(TaskContext*)0x00fe9b70
$2 = {cr3 = 0x250000, rip = 0x113c88, rflags = 0x6, reserved1 = 0x0, cs = 0x110008, ss = 0xfe0010,
fs = 0xfe0000, gs = 0x0, rax = 0xaf, rbx = 0xfe9b50, rcx = 0xfe8af0, rdx = 0x1, rdi = 0xfe77b0,
rsi = 0xfe9b70, rsp = 0xfeadb0, rbp = 0xfeadc0, r8 = 0x10dab50, r9 = 0x16, r10 = 0xfe9b50,
r11 = 0xfeacc3, r12 = 0xfeadd0, r13 = 0xfeae08, r14 = 0xf00000007, r15 = 0xfe9b50, fxsave_area = {
__elems_ = {0x0 <repeats 28 times>, 0xff, 0xff, 0x0 <repeats 130 times>, 0x75,
0x0 <repeats 351 times>}}}
特におかしいところはなさそう…
2 回目のキー入力によって発生する xHCI の割り込みハンドラ IntHandlerXHCI() の中で止めてみる。
Breakpoint 4, (anonymous namespace)::IntHandlerXHCI (
frame=0x114531 <(anonymous namespace)::TaskIdle(unsigned long, long)+17>) at interrupt.cpp:35
35 task_manager->SendMessage(1, Message{Message::kInterruptXHCI});
(gdb) i r
rax 0x0 0
rbx 0x0 0
rcx 0x0 0
rdx 0x0 0
rsi 0x0 0
rdi 0x2 2
rbp 0xfe8aa0 0xfe8aa0
rsp 0xfe8920 0xfe8920
r8 0x0 0
r9 0x0 0
r10 0x0 0
r11 0x0 0
r12 0x0 0
r13 0x0 0
r14 0x0 0
r15 0x0 0
rip 0x10ea98 0x10ea98 <(anonymous namespace)::IntHandlerXHCI(InterruptFrame*)+136>
eflags 0x2 [ ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
(gdb) x /6gx $rbp
0xfe8aa0: 0x0000000000fe8ad0 0x0000000000114531
0xfe8ab0: 0x0000000000000008 0x0000000000000202
0xfe8ac0: 0x0000000000fe8ad0 0x0000000000000010
[RBP] には元の RBP の値，[RBP+8] からは割り込みハンドラのスタックフレームが書かれている。 スタックフレームを整理してみると次のようになる。
| オフセット（バイト） | レジスタ | 値 |
|---|---|---|
| +0 | RIP | 0x00114531 |
| +8 | CS | 0x0008 |
| +16 | RFLAGS | 0x00000202 |
| +24 | RSP | 0x00fe8ad0 |
| +32 | SS | 0x0010 |
TaskIdle のループ部分を実行中に割り込まれたことが分かる。各レジスタともに期待通りの値。
1 回目の rpn コマンドが完了した後，最初のキー入力で MikanOS が落ちることが分かっている。 更に詳細な現象発生箇所を突き止めたい。
画面をよく観察すると，普段はメインループがイベントを受信するたびに更新しているカウンタが カーソル用タイマのイベントに合わせて 50（0.5 秒）ずつカウントアップしている。 2 回目の rpn コマンドを実行しようとすると，50 の倍数ではないカウント値を表示したまま，しばらくすると MikanOS が落ちる。 これがヒントになりそうだ。
1 回目の rpn コマンド完了後に IntHandlerXHCI のブレークポイントを有効化し，ブレークさせる。 （最初からこのブレークポイントを有効化してしまうと，"rpn 2 3 +" と 1 文字入力するたびにブレークしてしまい面倒だ）
IntHandlerXHCI でブレークしたら SwitchContext にブレークポイントを仕掛け，タスクスイッチの様子を観察してみる。 すると，ある時点で RDI == RSI となっているのを発見した。 これは，今回の現象とは関係ないだろうが，別のバグである。 （同じタスクに切り替えようとしている。おかしな動作になるわけではないが明らかに無駄な処理だ）
SwitchContext の処理を ni コマンドでどんどん進め，処理を追っていると IntHandlerLAPICTimer からの iretq が参照するスタックフレームの値が明らかにおかしくなっていることに気づいた。
RIP == 0x10ec91，ちょうど iretq に差し掛かったときにスタックフレームを表示してみた。
(gdb) x /1i $rip
=> 0x10ec91 <(anonymous namespace)::IntHandlerLAPICTimer(InterruptFrame*)+273>: iretq
(gdb) x /5gx $rsp
0x24cd68 <kernel_main_stack+1047816>: 0x00000000000012b6 0x0000000000000008
0x24cd78 <kernel_main_stack+1047832>: 0x0000000000000a82 0x000000000024cd98
0x24cd88 <kernel_main_stack+1047848>: 0x0000000000000010
スタックフレーム上の RIP の値が 0x12b6 になっている。これは明らかにおかしい。 カーネルは 0x100000 から配置されてるから，こんなところに機械語は無いはずだ。 直前の SwitchContext で変な値にジャンプしてしまったと推測されるので，MikanOS 再起動後に再度観察することにする。
SwitchContext でブレークした際に RDI == RSI == 0xfe6450 であった。 このとき，SwitchContext の iretq に到達した時点でのスタックフレームは次の通り。
Breakpoint 8, 0x000000000010e890 in SwitchContext ()
(gdb) x /5gx $rsp
0x24cbe0 <kernel_main_stack+1047424>: 0x000000000010ec0d 0x0000000000100008
0x24cbf0 <kernel_main_stack+1047440>: 0x0000000000000006 0x000000000024cc10
0x24cc00 <kernel_main_stack+1047456>: 0x0000000000690010
RIP == 0x10ec0d は IntHandlerLAPICTimer の中の call LAPICTimerOnInterrup の次の命令。 RSP == 0x24cc10 から，割り込みのスタックフレームを探して表示してみる。
IntHandlerLAPICTimer の処理を追いかけてみると RSP + 0x108 + 80 がスタックフレームのアドレスだった。
(gdb) x /5gx 0x24cc10 + 0x108 + 80
0x24cd68 <kernel_main_stack+1047816>: 0x0000000000000a72 0x0000000000000008
0x24cd78 <kernel_main_stack+1047832>: 0x0000000000000202 0x000000000024cd98
0x24cd88 <kernel_main_stack+1047848>: 0x0000000000000010
CS == 0x8，RFLAGS == 0x202，RSP == 0x24cd98，SS == 0x10 はいかにもそれっぽい値だが，RIP == 0xa72 だけ明らかにおかしい。
時系列をまとめると次のような流れ：
- 2 回目の rpn を実行するために何らかのキーを押す
- IntHandlerXHCI が起動する
- SwitchContext が呼ばれる。このときは RDI ≠ RSI，呼び出し元 RIP == 0x113c88
- SwitchContext が呼ばれる。このときは RDI == RSI，呼び出し元 RIP == 0x10ec0d
- 呼び出し元は IntHandlerLAPICTimer で，そのスタックフレームの RIP が変な値。
したがって IntHandlerXHCI 直後の SwitchContext を詳細に調べてみることにする。
IntHandlerXHCI 直後，初めて呼ばれる SwitchContext でブレークして詳細に調査する。
Breakpoint 7, 0x000000000010e782 in SwitchContext ()
(gdb) i r
rax 0x50 80
rbx 0x0 0
rcx 0xfe6780 16672640
rdx 0x0 0
rsi 0xfe77b0 16676784
rdi 0xfe6450 16671824
rbp 0xfe8aa0 0xfe8aa0
rsp 0xfe8948 0xfe8948
r8 0x80000000 2147483648
r9 0x4b0 1200
r10 0x0 0
r11 0x30 48
r12 0x0 0
r13 0x0 0
r14 0x0 0
r15 0x0 0
rip 0x10e782 0x10e782 <SwitchContext>
eflags 0x6 [ PF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
SwitchContext iretq 時点のスタックフレーム
(gdb) x /5gx $rsp
0xfe8920: 0x0000000000113c88 0x0000000000110008
0xfe8930: 0x0000000000000002 0x000000000024ced0
0xfe8940: 0x0000000000fe0010
RIP == 0x113c88 は Task::Sleep の中。call TaskManager::Sleep の次の命令。 RSP + 8 + 16 の位置に戻り先アドレスがあるので確認してみる。
(gdb) x /1gx 0x24ced0 + 8 + 16
0x24cee8 <kernel_main_stack+1048200>: 0x000000000010b7a8
RIP == 0x10b7a8 はメインループの Task::Sleep の次の sti 命令。 ここまでは想定通り… 0x10b7a8 でブレークして様子を見てみよう…
0x10b7a8 でちゃんとブレークできた。
その後実行を進めて見ると，SwitchContext を延々実行している。 で，そのうち MikanOS が死んでしまうことが分かった。
それぞれの SwitchContext でのレジスタの変化を見てみると何か分かるかも。 連続する 2 回の SwitchContext iretq でのレジスタ値は次の通り。
Breakpoint 8, 0x000000000010e890 in SwitchContext ()
2: /x *(unsigned long*)$rsp = 0x10ec0d
3: $rsp = (void *) 0x24cbe0 <kernel_main_stack+1047424>
(gdb) i r
rax 0x68 104
rbx 0x694b40 6900544
rcx 0xfe6780 16672640
rdx 0x0 0
rsi 0xfe6450 16671824
rdi 0xfe6450 16671824
rbp 0x24cd60 0x24cd60 <kernel_main_stack+1047808>
rsp 0x24cbe0 0x24cbe0 <kernel_main_stack+1047424>
r8 0x80000000 2147483648
r9 0x41a 1050
r10 0x0 0
r11 0x30 48
r12 0x693000 6893568
r13 0x695540 6903104
r14 0x694b64 6900580
r15 0x8 8
rip 0x10e890 0x10e890 <SwitchContext+270>
eflags 0x6 [ PF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
(gdb) c
Continuing.
Breakpoint 8, 0x000000000010e890 in SwitchContext ()
2: /x *(unsigned long*)$rsp = 0x10ec0d
3: $rsp = (void *) 0x24cbe0 <kernel_main_stack+1047424>
(gdb) i r
rax 0x69 105
rbx 0x694b40 6900544
rcx 0xfe6780 16672640
rdx 0x0 0
rsi 0xfe6450 16671824
rdi 0xfe6450 16671824
rbp 0x24cd60 0x24cd60 <kernel_main_stack+1047808>
rsp 0x24cbe0 0x24cbe0 <kernel_main_stack+1047424>
r8 0x80000000 2147483648
r9 0x41a 1050
r10 0x0 0
r11 0x30 48
r12 0x693000 6893568
r13 0x695540 6903104
r14 0x694b64 6900580
r15 0x8 8
rip 0x10e890 0x10e890 <SwitchContext+270>
eflags 0x6 [ PF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
うーん，RAX 以外は同じ値…（そして RAX は SwitchContext でブレークするたびに 1 ずつ増えるようだ）
IntHandlerLAPICTimer の入り口にブレークポイントを仕掛けると， 1 回目の SwitchContext のあと，IntHandlerLAPICTimer の入り口でブレークした。 このときのスタックフレーム上の RIP は正常な値。（RIP == 0x10f928 == Window::DrawTo の内部）
次に IntHandlerLAPICTimer の入り口で再度ブレークした。 このときのスタックフレーム上の RIP は異常な値。（RIP == 0x3fa）
0x3fa でブレークしてバックトレースを見てみる。
(gdb) bt
#0 0x00000000000003fa in ?? ()
#1 0x00000000001216d8 in usb::HIDBaseDriver::OnInterruptCompleted (
this=0x694b40 <usb::memory_pool+15040>, ep_id=..., buf=<optimized out>, len=8)
at usb/classdriver/hid.cpp:57
#2 0x000000000011e1d4 in usb::Device::OnInterruptCompleted (this=0x693000 <usb::memory_pool+8064>,
ep_id=..., buf=0x694b64 <usb::memory_pool+15076>, len=8) at usb/device.cpp:186
#3 0x0000000000120b7b in usb::xhci::Device::OnTransferEventReceived (
this=0x693000 <usb::memory_pool+8064>, trb=...) at usb/xhci/device.cpp:249
#4 0x000000000011edc9 in (anonymous namespace)::OnEvent (xhc=..., trb=...) at usb/xhci/xhci.cpp:218
#5 usb::xhci::ProcessEvent (xhc=...) at usb/xhci/xhci.cpp:468
#6 0x000000000011f8eb in usb::xhci::ProcessEvents () at usb/xhci/xhci.cpp:537
#7 0x000000000010b86a in KernelMainNewStack (frame_buffer_config_ref=..., memory_map_ref=...,
acpi_table=..., volume_image=<optimized out>) at main.cpp:189
#8 0x000000000010e77f in KernelMain ()
1216d8 付近にはこんな命令がある
1216d5: ff 50 20 call QWORD PTR [rax+0x20]
1216d8: 48 89 c1 mov rcx,rax
1216d5 でブレークしてみたら何か分かる気がする。実際にブレークしてみた。
(gdb) x /1i $rip
=> 0x1216d5 <usb::HIDBaseDriver::OnInterruptCompleted(usb::EndpointID, void const*, int)+101>:
call QWORD PTR [rax+0x20]
(gdb) p /x $rax
$22 = 0x101ff8
[RAX + 0x20] == [0x102018] == 0x3 だが，ここにカーネルの機械語は置かれてない。これがバグの原因ぽい。
念の為，エラーになる前の RIP == 0x1216d5 でブレークしたらどんな様子だろうか。
(gdb) x /1gx 0x102018
0x102018 <_ZTVN3usb4xhci6DeviceE+48>: 0x00000000001209c0
[RAX + 0x20] == [0x102018] == 0x1209c0 であり，これは usb::xhci::Device::InterruptIn の先頭アドレス。 ということで 0x102018 番地に変なアドレスが書かれてしまうのが直接のバグ原因。
0x1209c0 にウォッチポイント（変数読み書きに対するブレークポイントのようなもの）を仕掛けて，書き換えてる犯人を探す。
Hardware watchpoint 21: *(unsigned long*)0x102018
Old value = 1182144
New value = 3
0x00000000010dee04 in ?? ()
2: /x *(unsigned long*)$rsp = 0xfead10
3: $rsp = (void *) 0xfeac98
(gdb) i r
rax 0x0 0
rbx 0x2 2
rcx 0x3 3
rdx 0x1 1
rsi 0x10e0fd0 17698768
rdi 0xfedf4c 16703308
rbp 0xfeaca0 0xfeaca0
rsp 0xfeac98 0xfeac98
r8 0x4 4
r9 0x0 0
r10 0xffffff33 4294967091
r11 0x2d 45
r12 0x10e0fa0 17698720
r13 0x10ddc10 17685520
r14 0xfead30 16690480
r15 0x0 0
rip 0x10dee04 0x10dee04
eflags 0x246 [ PF ZF IF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
(gdb) bt
#0 0x00000000010dee04 in ?? ()
#1 0x0000000000fead10 in ?? ()
#2 0x0000000000fead60 in ?? ()
#3 0x000000000011a470 in Terminal::ExecuteFile (this=0xfead10, file_entry=...,
command=0x12b28b <operator new(unsigned long)+27> "I\211\306H\205\300u)E1\366f.\017\037\204",
first_arg=<optimized out>) at terminal.cpp:264
直接の犯人は 0x10dee04 にある mov 命令だが，そもそもここにカーネルは無い。では何があるかというと rpn コマンドの本体。 このウォッチポイントに引っかかったのは，1 回目の rpn コマンドを実行しようとしてエンターキーを押した後， rpn コマンドが完了する前の段階だった。
RIP == 0x11a470 は Terminal::ExecuteFile で rpn コマンドのエントリポイントに対する call 命令の次の命令。 この call 命令でブレークして様子を見る。
(gdb) b *0x11a46e
Breakpoint 23 at 0x11a46e: file terminal.cpp, line 264.
(gdb) c
Continuing.
Breakpoint 23, Terminal::ExecuteFile (this=0xfedf20, file_entry=..., command=0xfedf44 "rpn",
first_arg=<optimized out>) at terminal.cpp:264
264 auto ret = f(argv.size(), &argv[0]);
2: /x *(unsigned long*)$rsp = 0xfedf44
3: $rsp = (void *) 0xfeacb0
(gdb) i r
rax 0x10dece0 17689824
rbx 0xfead10 16690448
rcx 0xfedf4c 16703308
rdx 0x14a7c0 1353664
rsi 0x10e0fd0 17698768
rdi 0x4 4
rbp 0xfead60 0xfead60
rsp 0xfeacb0 0xfeacb0
r8 0x14a780 1353600
r9 0x0 0
r10 0x14a780 1353600
r11 0x0 0
r12 0x10e0fa0 17698720
r13 0x10ddc10 17685520
r14 0xfead30 16690480
r15 0x0 0
rip 0x11a46e 0x11a46e <Terminal::ExecuteFile(fat::DirectoryEntry const&, char*, char*)+750>
eflags 0x202 [ IF ]
cs 0x8 8
ss 0x10 16
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
RAX == 0x10dece0 なので，rpn のエントリポイント（main 関数）がここにロードされていることが分かる。 main 関数の ret にブレークを仕掛けて実行してみると 0x10dee04 でウォッチポイント作動。
(gdb) b *0x10dee33
Breakpoint 24 at 0x10dee33
(gdb) c
Continuing.
Hardware watchpoint 21: *(unsigned long*)0x102018
Old value = 1182144
New value = 3
0x00000000010dee04 in ?? ()
2: /x *(unsigned long*)$rsp = 0xfead10
3: $rsp = (void *) 0xfeac98
この命令は，rpn コマンドで stack に値を書き込んでいる処理。
readelf -s rpn でシンボルテーブルを確認すると long stack[100] が 0x102010 に配置されている。
つまり，rpn コマンドの実行により 0x102018 が書き換えられていることが確定。
Task::InitContext でログを出さないときの _ZTVN3usb4xhci6DeviceE の位置とサイズ。
980: 0000000000101fe8 64 OBJECT GLOBAL DEFAULT 1 _ZTVN3usb4xhci6DeviceE
0x101fe8 + 48 = 0x102018
Task::InitContext でログを出すようにするとこのシンボルの位置が大分ずれる。
980: 0000000000102008 64 OBJECT GLOBAL DEFAULT 1 _ZTVN3usb4xhci6DeviceE
ログを出すようにしたことにより，不正なメモリ書き込みの影響が隠された，ということが分かった。
0x102038 + 48 = 0x102038
rpn 2 3 + とするとスタックの先頭 2 要素に書き込まれる。
long stack[100] が 0x102010 に配置されているので，0x102010 と 0x102018 である。
ログ無しでは，これがちょうど _ZTVN3usb4xhci6DeviceE+48 と重なるアドレスとなる。
ログ有りでは 0x20 だけずれており，現象が回避できた。