WasmLinux上のBusyboxで ifconfig -a するとpanicする。

(user) syscall = 57
TLS[77]: 1 -> 38888800
[    2.209332] BUG: failure at fs/inode.c:611/clear_inode()!

[    2.209733] Kernel panic - not syncing: BUG!

[    2.210253] ---[ end Kernel panic - not syncing: BUG! ]---

panic.

さすがにこれは不便すぎるのでデバッグしたい。。

okuoku

なぜ `BUG` したのか

Linuxカーネルにおける BUG は普通のC言語で言うところの assert に相当する。ここでは inode->i_data.nrpages が非ゼロだったということになる。

バックトレースを確認すると:

>	runner.exe!mod_admin(unsigned __int64 * in=0x000002d4bf75fdf8, unsigned __int64 * out=0x000002d47dea0000) Line 1334	C++	Symbols loaded.
 	runner.exe!w2c_env_nccc_call64(w2c_env * env=0x0000000000000000, unsigned int inptr=0x418bfdf0, unsigned int outptr=0x00000000) Line 1515	C++	Symbols loaded.
 	runner.exe!w2c_kernel_host_panic(w2c_kernel * instance=0x000002d67e062940) Line 1702505	C	Symbols loaded.
 	runner.exe!w2c_kernel_lkl_panic_blink(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x00000001) Line 1690796	C	Symbols loaded.
 	runner.exe!w2c_kernel_panic(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x00000000, unsigned int var_p1=0x00000000) Line 1693737	C	Symbols loaded.
 	runner.exe!w2c_kernel_clear_inode(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38410681) Line 1408950	C	Symbols loaded.
 	runner.exe!w2c_kernel_proc_evict_inode(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38410681) Line 1414539	C	Symbols loaded.
 	runner.exe!w2c_kernel_evict(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38410681) Line 1409312	C	Symbols loaded.
 	runner.exe!w2c_kernel_iput(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38410681) Line 1410181	C	Symbols loaded.
 	runner.exe!w2c_kernel_dentry_unlink_inode(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38411088) Line 1290660	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_dentry_kill(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38411088) Line 1289878	C	Symbols loaded.
 	runner.exe!w2c_kernel_dput(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x38411088) Line 1289646	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_fput(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x383e58c0) Line 1393903	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_0x5F_fput(w2c_kernel * instance=0x000002d67e062940, unsigned int var_p0=0x383e58c0) Line 1394068	C	Symbols loaded.
 	runner.exe!w2c_kernel_task_work_run(w2c_kernel * instance=0x000002d67e062940) Line 501593	C	Symbols loaded.

確かに clear_inode は呼ばれている。この部分のwasm2c出力は:

void w2c_kernel_clear_inode(w2c_kernel* instance, u32 var_p0) {
  u32 var_l1 = 0, var_l2 = 0;
  FUNC_PROLOGUE;
  u32 var_i0, var_i1, var_i2;
  var_i0 = instance->w2c_0x5F_stack_pointer;
  var_i1 = 80u;
  var_i0 -= var_i1;
  var_l1 = var_i0;
  instance->w2c_0x5F_stack_pointer = var_i0;
  var_i0 = 0u;
  w2c_kernel_arch_local_irq_restore(instance, var_i0);
  var_i0 = var_p0;
  var_i1 = 300u;
  var_i0 += var_i1;
  var_i0 = i32_load(&instance->w2c_memory, (u64)(var_i0)); // ★ inode->i_data.nrpages をロード
  if (var_i0) {goto var_B4;} // ★ ここで var_B4 にjumpするとpanic

というわけでブレークポイントを置いて再実行する。

[stdout]:           LOOPBACK  MTU:65536  Metric:1
[stdout]:           RX packets:0 errors:0 dropped:0 overruns:0 frame:0
[stdout]:           TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
[stdout]:           collisions:0 txqueuelen:1000
[stdout]:           RX bytes:0 (0.0 B)  TX bytes:0 (0.0 B)
[stdout]:
[stdout]: sit0      Link encap:IPv6-in-IPv4
[stdout]:           NOARP  MTU:1480  Metric:1
TLS[77]: 1 -> 38888800
[stdout]:           RX packets:0 errors:0 dropped:0 overruns:0 frame:0
[stdout]:           TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
[stdout]:           collisions:0 txqueuelen:1000
[stdout]:           RX bytes:0 (0.0 B)  TX bytes:0 (0.0 B)
[stdout]:
[    0.865146] Exiting userthread.

いや正常に実行できちゃったんだけど。。つまり、問題は タイミング依存の問題 ということになる。

何度か実行しているとpanicした。このときの inode->i_data.nrpages は 0xac384107 明かに nrpages(ページ数)の数ではないので、 ヒープ破壊 ということになる。

okuoku

そもそもポインタがおかしい

この関数の引数 clear_inode(struct inode *inode) はポインタなのに、(クラッシュ時の)実際の値は 0x38410681 で安定している。常識的に考えて、 ポインタの値が奇数になることはありえない から、このinodeを拾ってくるタイミングで既に何かが破壊されていることになる。

Backtraceを逆に辿ると、

ローカル変数が破壊されていないと仮定すると、 dentry_unlink_inode に渡されている struct dentry * が怪しいということになる。この(WebAssemblyメモリ内の)アドレスは 0x38411088 で一定なようだ。こちらはこの値でも正常に終了することもある。

okuoku

書き込みを見つける

w2cのメモリはダイナミックに確保しているので、起動のたびにデータブレークを再設定する必要がある。 &the_linux.w2c_memory.data[0x38411088 + 40] 。

問題の値 0x38410681 を書き込んでいるのは:

 	runner.exe!i32_store(wasm_rt_memory_t * mem=0x000002666b5cc970, unsigned __int64 addr=0x00000000384110b0, unsigned int value=0x38410681) Line 163	C	Symbols loaded.
>	runner.exe!w2c_kernel_0x5F_d_add(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x38411088, unsigned int var_p1=0x38410681) Line 1296234	C	Symbols loaded.
 	runner.exe!w2c_kernel_d_splice_alias(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x38410681, unsigned int var_p1=0x38411088) Line 1294435	C	Symbols loaded.
 	runner.exe!w2c_kernel_proc_lookup_de(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x38410820, unsigned int var_p1=0x38411088, unsigned int var_p2=0x383d3550) Line 1439068	C	Symbols loaded.
 	runner.exe!w2c_kernel_proc_tgid_net_lookup(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x38410820, unsigned int var_p1=0x38411088, unsigned int var_p2=0x00000101) Line 549935	C	Symbols loaded.
 	runner.exe!w2c_kernel_path_openat(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x418bfe08, unsigned int var_p1=0x418bfea8, unsigned int var_p2=0x00000041) Line 1305920	C	Symbols loaded.
 	runner.exe!w2c_kernel_do_filp_open(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x00000000, unsigned int var_p1=0x00000001, unsigned int var_p2=0x418bfea8) Line 1305148	C	Symbols loaded.
 	runner.exe!w2c_kernel_do_sys_openat2(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0xffffff9c, unsigned int var_p1=0x38351000, unsigned int var_p2=0x418bfec8) Line 1385057	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_se_sys_openat(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0xffffff9c, unsigned int var_p1=0x3e24d921, unsigned int var_p2=0x00008000, unsigned int var_p3=0x000001b6) Line 1385280	C	Symbols loaded.
 	runner.exe!w2c_kernel_lkl_syscall(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x00000038, unsigned int var_p1=0x00000004, unsigned int var_p2=0x3e43fbf0) Line 1690123	C	Symbols loaded.
 	runner.exe!w2c_kernel_syscall_0(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x00000038, unsigned int var_p1=0x00000004, unsigned int var_p2=0x3e43fbf0) Line 1702338	C	Symbols loaded.
 	runner.exe!w2c_kernel_syscall(w2c_kernel * instance=0x000002666b5cc960, unsigned int var_p0=0x00000038, unsigned int var_p1=0x00000004, unsigned int var_p2=0x3e43fbf0) Line 191309	C	Symbols loaded.
 	runner.exe!runsyscall32(unsigned int no=0x00000038, unsigned int nargs=0x00000004, unsigned int in=0x3e43fbf0) Line 618	C++	Symbols loaded.

d_splice_alias に 0x38410681 を渡している proc_lookup_de ということになる。

この中でinodeはprocfs内で確保されている(procfsは自前の alloc_inode superblock opを持っている。)

okuoku

freelistを監視する

普通、slabアロケーターが異常なポインタを急に導出してくるということは考えづらいので、解放したメモリをfreelistに繋いだあと、そのアドレスを格納した領域が破壊されていると考えるのが自然なんではないか。

マップファイルから、グローバル変数 proc_inode_cachep のアドレスは 0x1638bc とわかる。これが struct kmem_cache * なので、何回かポインタを辿る必要がある。

  1638bc   8983b2        4                 proc_inode_cachep

proc_inode_cachep->cpu_slab->freelist というわけで3回かな。

(uint32_t*)&the_linux.w2c_memory.data[0x1638bc]
(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[0x1638bc]]
(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[0x1638bc]]]
(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[*(uint32_t*)&the_linux.w2c_memory.data[0x1638bc]]]]

なんか超頭わるい感じだな。。

これで監視してみると、謎のアドレスが確かに存在する。

0x1638bc = proc_inode_cachep のアドレスを格納
proc_inode_cachep の先頭 = cpu_slab のアドレスを格納
cpu_slab の先頭 = freelist

つまり、異常なアドレスをfreeして謎のオブジェクトをfreelistに繋いだということだろうか。

okuoku

確かにタイマ割り込みで変なアドレスをfreeしている

 	runner.exe!i32_store(wasm_rt_memory_t * mem=0x000001ae3d525b20, unsigned __int64 addr=0x000000003c1aea20, unsigned int value=0x38410659) Line 163	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_kmem_cache_free(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x38249780, unsigned int var_p1=0x38410659, unsigned int var_p2=0xdeadcafe) Line 1543764	C	Symbols loaded.
 	runner.exe!w2c_kernel_kfree(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x38410659) Line 1558178	C	Symbols loaded.
 	runner.exe!w2c_kernel_kvfree(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x38410659) Line 1395035	C	Symbols loaded.
 	runner.exe!w2c_kernel_rcu_process_callbacks(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x001e4554) Line 1474546	C	Symbols loaded.
>	runner.exe!w2c_kernel_0x5F_do_softirq(w2c_kernel * instance=0x000001ae3d525b10) Line 1100307	C	Symbols loaded.
 	runner.exe!w2c_kernel_0x5F_irq_exit_rcu(w2c_kernel * instance=0x000001ae3d525b10) Line 1100571	C	Symbols loaded.
 	runner.exe!w2c_kernel_irq_exit(w2c_kernel * instance=0x000001ae3d525b10) Line 1100595	C	Symbols loaded.
 	runner.exe!w2c_kernel_run_irq(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x00000001) Line 1691874	C	Symbols loaded.
 	runner.exe!w2c_kernel_lkl_trigger_irq(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x00000001) Line 1691845	C	Symbols loaded.
 	runner.exe!w2c_kernel_timer_fn(w2c_kernel * instance=0x000001ae3d525b10, unsigned int var_p0=0x00000000) Line 504418	C	Symbols loaded.
 	runner.exe!thr_timer(int objid=0x00000008) Line 1383	C++	Symbols loaded.

0xdeadcafe は callerのダミー値。これはWasmLinux独自。

で、実際の kvfree はRCUのためにdeferされていて、問題はこれが呼ばれるタイミングまでに発生している。

可能性がありそうなのは3つで、

そもそも __is_kvfree_rcu_offset が上手くいってないんじゃないか問題
kvfree_rcu を呼ぶときのアドレスがおかしいんじゃないか問題
kvfree_rcu を呼んだあとCPU側のキューが破壊されているんじゃないか問題

実はこの機構は 関数ポインタの値が4096を下回ることが無い と仮定している。

このbacktraceにおけるoffsetを確認してみると 0xa27 。これは関数ポインタとしては __d_free を指している。これはダメっぽいな。。

普通にRCUのコールバックに指定されている。

この仕様は2011年に導入されたようだ。

okuoku

関数ポインタの値が `4096` 以上になることをどうやって保証するか問題

パッと思いつくのは、

ダミー関数を4096個生成する
カーネルをリロケータブルにしてオフセットする
RCUでは関数ポインタを4096だけオフセットする
kfree_rcu でoffsetを負値にエンコードする

簡単なのは 4. かなぁ。。1.は単に面倒でビルドにも時間が掛かる。2.はパフォーマンスペナルティ有。3.は改造箇所が多すぎる。

4.の場合、逆に関数ポインタが2GiBオフセットを越えられなくなる。まぁ常識的なシチュエーションではこれはありえないから問題ないだろう。

okuoku

というわけで適当にオフセットした

これにより安定して ifconfig -a できるようになった。

いやこれどうしようかな。。リンカとかほんと書きたくないんだよな。。

なぜ BUG したのか

そもそもポインタがおかしい

書き込みを見つける

freelistを監視する

確かにタイマ割り込みで変なアドレスをfreeしている

関数ポインタの値が 4096 以上になることをどうやって保証するか問題

というわけで適当にオフセットした

なぜ `BUG` したのか

関数ポインタの値が `4096` 以上になることをどうやって保証するか問題