注
自分の頭の整理のためのエントリーです。 よって超長い。
mruby-spec
以前、mrubyでruby/specを走らせるやつを書いたのですが、 その後どうなったのかまとめてみます。
成果
- mruby本体のSEGVを3つなおした。
ruby/specで、まず手を付けていたのはlanguage specでした。 言語の基礎が壊れてたらイカンだろうということで根っこから見ています。
正直言ってまだ走り切ることも困難です。というのもSEGVするから。 SEGVするとそこから先のspecを走らせることができなくなるため、地道に直していました。
https://github.com/mruby/mruby/pull/3204
大体はmac上でデバッグしているのでlldbを使いました。 lldbでlanguage specを走らせてみて、どこで止まったか追ってみます。 mrubyのcommit hashは d58c2585d4d63f13beeb890046ce6c7b514fab91 でした
$ pwd ksss/mruby-spec $ lldb mruby/bin/mruby (lldb) run mspec/bin/mspec-run spec/language ... いっぱいspecが落ちる表示が出る ... [/ | ======== 20% | 00:00:00] 19F 51EProcess 3230 stopped * thread #1: tid = 0x16e74f, 0x000000010006eb9e mruby`get_closure_irep(mrb=0x00000001003002d0, level=0) + 254 at eval.c:31, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x4800000001) frame #0: 0x000000010006eb9e mruby`get_closure_irep(mrb=0x00000001003002d0, level=0) + 254 at eval.c:31 28 if (!e) return NULL; 29 proc = c->cibase[e->cioff].proc; 30 -> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) { 32 return NULL; 33 } 34 return proc->body.irep;
うんぜんぜんわからん。ちなみに止まる部分は実行する毎に変わったりします。
Cレベルでのバックトレースを取ってみます。
(lldb) bt * thread #1: tid = 0x16fbc3, 0x000000010006eb9e mruby`get_closure_irep(mrb=0x0000000100400390, level=0) + 254 at eval.c:31, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x3500000001) * frame #0: 0x000000010006eb9e mruby`get_closure_irep(mrb=0x0000000100400390, level=0) + 254 at eval.c:31 frame #1: 0x000000010006e985 mruby`search_variable(mrb=0x0000000100400390, vsym=326, bnest=0) + 37 at eval.c:44 frame #2: 0x000000010006e903 mruby`patch_irep(mrb=0x0000000100400390, irep=0x0000000101865dd0, bnest=0) + 723 at eval.c:122 frame #3: 0x000000010006e595 mruby`create_proc_from_string(mrb=0x0000000100400390, s="x=1", len=3, binding=mrb_value @ 0x00007fff5fbfd1c0, file="(eval)", line=1) + 1205 at eval.c:194 frame #4: 0x000000010006ddef mruby`f_eval(mrb=0x0000000100400390, self=mrb_value @ 0x00007fff5fbfd398) + 191 at eval.c:215 frame #5: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100400390, proc=0x000000010202cca0, pc=0x000000010183ab90) + 6613 at vm.c:1150 frame #6: 0x000000010003d427 mruby`mrb_vm_run(mrb=0x0000000100400390, proc=0x000000010107e670, self=mrb_value @ 0x00007fff5fbfe080, stack_keep=0) + 135 at vm.c:759 frame #7: 0x00000001000458fb mruby`mrb_top_run(mrb=0x0000000100400390, proc=0x000000010107e670, self=mrb_value @ 0x00007fff5fbfe0f0, stack_keep=0) + 187 at vm.c:2440 frame #8: 0x000000010006302f mruby`load_exec(mrb=0x0000000100400390, p=0x000000010201d420, c=0x0000000101851ee0) + 1183 at parse.y:5694 frame #9: 0x0000000100062b73 mruby`mrb_load_file_cxt(mrb=0x0000000100400390, f=0x00007fff79291218, c=0x0000000101851ee0) + 67 at parse.y:5703 frame #10: 0x0000000100094217 mruby`load_rb_file(mrb=0x0000000100400390, filepath=mrb_value @ 0x00007fff5fbfe410) + 247 at mrb_require.c:425 frame #11: 0x000000010009305e mruby`load_file(mrb=0x0000000100400390, filepath=mrb_value @ 0x00007fff5fbfe450) + 142 at mrb_require.c:437 frame #12: 0x0000000100092a13 mruby`mrb_load(mrb=0x0000000100400390, filename=mrb_value @ 0x00007fff5fbfe490) + 51 at mrb_require.c:455 frame #13: 0x00000001000931d5 mruby`mrb_f_load(mrb=0x0000000100400390, self=mrb_value @ 0x00007fff5fbfe4f0) + 133 at mrb_require.c:470 frame #14: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100400390, proc=0x000000010107ec40, pc=0x00000001004a0e98) + 6613 at vm.c:1150 frame #15: 0x000000010003d427 mruby`mrb_vm_run(mrb=0x0000000100400390, proc=0x0000000101047950, self=mrb_value @ 0x00007fff5fbff1d0, stack_keep=0) + 135 at vm.c:759 frame #16: 0x00000001000458a4 mruby`mrb_top_run(mrb=0x0000000100400390, proc=0x0000000101047950, self=mrb_value @ 0x00007fff5fbff240, stack_keep=0) + 100 at vm.c:2434 frame #17: 0x000000010006302f mruby`load_exec(mrb=0x0000000100400390, p=0x0000000101019820, c=0x0000000100432020) + 1183 at parse.y:5694 frame #18: 0x0000000100062b73 mruby`mrb_load_file_cxt(mrb=0x0000000100400390, f=0x00007fff79291050, c=0x0000000100432020) + 67 at parse.y:5703 frame #19: 0x0000000100001509 mruby`main(argc=3, argv=0x00007fff5fbff668) + 905 at mruby.c:226 frame #20: 0x00007fff9b92e5ad libdyld.dylib`start + 1 frame #21: 0x00007fff9b92e5ad libdyld.dylib`start + 1
一見意味不明ですが、よくみるとeval.cでcreate_proc_from_string
関数に"x=1"
という文字列を渡していることに気が付きます。
$ cd spec && pwd ksss/mruby-spec/spec $ git grep x=1 language language/and_spec.rb: # evaluates (x=1) and (y=2) language/ensure_spec.rb: eval('x=1') # to prevent opts from triggering
どうやらlanguage/ensure_spec.rbがクサいっぽいです。
it "in no-exception scenarios, is the value of the last statement of the protected body" do begin v = 1 eval('x=1') # to prevent opts from triggering v ensure v = 2 end.should == 1 end
ありました。eval('x=1')
の部分が実に怪しいです。
しかしながら単純にmruby -e 'eval("x=1")'
としてもSEGVしません。
再現コードを書こうにも、mspecのコードを読んでできるだけ余計なコードを削除して展開して……。 とやっていると、「ある時点でメソッドを展開するとSEGVが起こらなくなる」という現象に遭遇しました。 最初はサッパリでしたが、途中で「もしやメソッドの呼び出しスタックが深くなるとSEGVが起こりやすくなるのでは?」とひらめき、
1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{ 1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{ begin eval('raise') rescue => e print e.backtrace end }}}}}}}} }}}}}}}}
とすることでSEGVを再現できることをたまたま発見できました。
ところがどっこい。 この再現コードはこれまでと全く違う部分でSEGVしているようです。
(lldb) run t.rb Process 4744 launched: '/Users/yuki/src/github.com/ksss/mruby-spec/mruby/bin/mruby' (x86_64) Process 4744 stopped * thread #1: tid = 0x173171, 0x00007fff95b04132 libsystem_c.dylib`strlen + 18, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x0) frame #0: 0x00007fff95b04132 libsystem_c.dylib`strlen + 18 libsystem_c.dylib`strlen: -> 0x7fff95b04132 <+18>: pcmpeqb (%rdi), %xmm0 0x7fff95b04136 <+22>: pmovmskb %xmm0, %esi 0x7fff95b0413a <+26>: andq $0xf, %rcx 0x7fff95b0413e <+30>: orq $-0x1, %rax (lldb) up frame #1: 0x0000000100030d8b mruby`mrb_str_cat_cstr(mrb=0x0000000100600000, str=mrb_value @ 0x00007fff5fbfe380, ptr=0x0000000000000000) + 43 at string.c:2585 2582 MRB_API mrb_value 2583 mrb_str_cat_cstr(mrb_state *mrb, mrb_value str, const char *ptr) 2584 { -> 2585 return mrb_str_cat(mrb, str, ptr, strlen(ptr)); 2586 } 2587 2588 MRB_API mrb_value (lldb) up frame #2: 0x000000010000645d mruby`mrb_restore_backtrace(mrb=0x0000000100600000) + 541 at backtrace.c:415 412 mrb_str_cat(mrb, mrb_entry, &entry->sep, 1); 413 } 414 -> 415 mrb_str_cat_cstr(mrb, mrb_entry, mrb_sym2name(mrb, entry->method_id)); 416 } 417 418 mrb_ary_push(mrb, backtrace, mrb_entry); (lldb) up frame #3: 0x0000000100014eec mruby`exc_get_backtrace(mrb=0x0000000100600000, exc=mrb_value @ 0x00007fff5fbfe510) + 156 at error.c:190 187 backtrace = mrb_iv_get(mrb, exc, attr_name); 188 if (mrb_nil_p(backtrace)) { 189 if (mrb_obj_ptr(exc) == mrb->backtrace.exc && mrb->backtrace.n > 0) { -> 190 backtrace = mrb_restore_backtrace(mrb); 191 mrb->backtrace.n = 0; 192 mrb->backtrace.exc = 0; 193 } (lldb) up frame #4: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100600000, proc=0x000000010081f670, pc=0x000000010064ba58) + 6613 at vm.c:1150 1147 ci->argc = n; 1148 ci->nregs = n + 2; 1149 } -> 1150 result = m->body.func(mrb, recv); 1151 mrb_gc_arena_restore(mrb, ai); 1152 if (mrb->exc) goto L_RAISE; 1153 /* pop stackpos */
どうやらException#backtrace
を呼び出した時にmrb_sym2name(mrb, entry->method_id)
がNULL
を返してしまい、strlen(NULL)
のような形になってしまっているようです。entry->method_id
は23459
のような数字でした。これはシンボルのIDのはずなのですが、2万個もシンボルを作っていないはずなので多すぎます。この値が異常っぽいです。それゆえmrb_sym2name
はシンボルIDから文字列に変換するメソッドなのですが、該当するシンボルがないのでNULL
を返しているようです。
そもそもmrubyのbacktraceはどうやって取っているのでしょうか? それすら全くわからなかったので、ひたすらコードを読みました。
すると、次のようなことが見えてきました。
- mrubyのbacktrace情報は
mrb->c->ci
から取ってきている mrb->c
はstruct mrb_context
のことで、struct mrb_context
にはcibase
,ci
,ciend
というメンバーがある。cibase
は単に配列で、ci
は配列の現在位置、ciend
はメモリを確保している最後の印。- 最初に
cibase
に長さ32個分のメモリを確保、ci = cibase
として初期化される。 - mruby側でメソッドを呼び出すたびに
ci
ポインタは一つ進み、これまでどういうスタックで呼ばれてきたのかを記録している。 ci
がciend
までくると、mrb_realloc
で確保するメモリが2倍に伸長される。
backtraceはci
の位置から一つづつcibase
の位置にもどりつつスタックの情報をbacktrace用に作っていて、肝心要のentry->method_id
はci->mid
からコピーしている。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/backtrace.c#L147
当然ci->mid
は今のスタックのメソッド名(シンボル)でおかしな値はここからコピーされていることがわかった。
さて、ci->mid
はどこから来るのか。この値はシンボルなので加減算はされないだろう。
さらにあたりをつけると、こんな異常で毎回大きく異る値をとり得るのは、未初期化な場合だろう。
ではciスタックは、どこで作られるんだろう。
実は2箇所しかない。 初期化時と伸長時だ。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/vm.c#L93 https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/vm.c#L226
ヤバイこのまま細かく書いているといつまでたっても終わらない。どんどん巻いていくと、mrb_calloc
はじつはmemset
で0初期化する処理が含まれているのでここで異常な値が入るとは考えにくい。
そしてmrb_realloc
はその名の通りrealloc
するので0初期化しない。
さらに、このmrb_realloc
でcibase
を取り直しているcipush
はmrubyのeval
メソッドからmrb_top_run
を通じて呼ばれている。
そしてなんと、このパスではci->midはなにも操作されない。realloc
で確保されたメモリではあるが、野ざらしで雑草がぼうぼうに生えた空き地があるだけだ。その雑草が23459
。ようやく犯人(草)を掴んだ。
ここで雑草を抜いて綺麗にしておけばなんとかなる。
mrubyの場合、mid=0がCRubyでの<main>
を意味するようだ。mrubyではこの場合、単にメソッド名を表示していない。
$ ruby -e 'eval("raise")' -e:1:in `eval': (eval):1:in `<main>' (RuntimeError) from -e:1:in `eval' from -e:1:in `<main>'
$ mruby -e 'eval("raise")' trace: [0] (eval):1 [1] -e:1 (eval):1: RuntimeError
これでようやく一つ倒した。ここまでで一週間以上かかっている。
https://github.com/mruby/mruby/pull/3206
さて、ここまできても最初に見つけたSEGVはなおっていない。つらい。 気を取り直して調べていこう。
lldbで見つけた部分を思い出そう。
28 if (!e) return NULL; 29 proc = c->cibase[e->cioff].proc; 30 -> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) { 32 return NULL; 33 } 34 return proc->body.irep;
ここでいろいろ調べてみると、e->cioff
は-1
であることがわかった。
(lldb) p e->cioff (ptrdiff_t) $0 = -1
前回、cibase
はスタックの最初であることが分かっていた。cibase[-1]
ではあきらかにおかしい。つまりこの時点でe->cioff
か-1
なのがおかしいことになる。
e->cioff
とはなにか。そもそもe(REnv*)
とはなにか。
REnvで検索していくと、mrb_callinfo
とRProc
という構造体にメンバーとして含まれている。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/include/mruby/proc.h#L32-L40 https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/include/mruby.h#L72-L85
また、REnv型としてメモリ確保されているのはproc.cのenv_new
、さらにenv_new
をclosure_setup
が呼んでいる。
https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/src/proc.c#L37-L64
closure...クロージャーと言えば、なぜか外側の変数をメソッド内で保持している不思議な奴だった気がするやつだ。 ここで、「struct REnvは外側の環境を保存しておくためのものではないか?」という仮説が浮かび上がる。 ほかにも「環境変数を表すやつか?」とかいろんな仮説が浮かんでは死んでいった。今回もそうだろうか?
proc.hには気になるマクロがある。
そういえば問題はe->cioff = -1
のときなんだった。忘れてた。
これはMRB_ENV_UNSHARE_STACK
された時と見るのが可能性が高そうだ。
多分この数字によってREnvのモードが変わる的な数字だと思う。
cioffの名の通り、おそらくciのoffsetなんだろう。
https://github.com/ksss/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/proc.c#L45
をみると、cibaseからciがどれぐらい動いているのかを保存している。 おそらくREnvがciスタックにアクセスしたいときに、どのスタックを呼び出せばいいかを保存しているものと見た。
cioff=-1
ということはciスタックを参照することはないんだけど、REnvが使われるかもしれないから残しておきたいフラグなのかなあと推測。
MRB_ENV_UNSHARE_STACK
が使われるのはcipop
された時だ。自分でも何を言っているのかわからなくなってきた。
vm.cを読むと、cipop
とcipush
という関数がある。cipop
というからにはciスタックを元に戻る操作なんだろう。逆にcipush
はci
スタックを積み上げる操作。
さらにヒントになったのが、blameしていてみつけたこのPR
この再現コードでいわゆる"unshare"なREnvを使うことができる。
いろいろいじってみると、たしかに問題のeval.cのあの部分で問題を再現できるのだけど、どうもSEGVにならない。
28 if (!e) return NULL; 29 proc = c->cibase[e->cioff].proc; 30 -> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) { 32 return NULL; 33 } 34 return proc->body.irep;
ここでprocはNULLを指しているからだ。
ここで前回の問題が浮かんだ。"ciスタックが深いと再現するのでは?" そうしてできたのがPRの再現コード。
def m Proc.new { eval('raise') } end 1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{ 1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{ m.call }}}}}}}} }}}}}}}}
ついに来た。これで勝つるというやつだ。
eval.cで問題になっているのは、eval
メソッドでRubyコード文字列を引数にして実行した場合に変数も使えるようにしている部分だった。
ここではcioffからciスタックをたどって、その時点の実行コードを読み込もうとしていたが、mメソッド内のciスタックはすでにpopしているのでeはunsharedになっている。これをeval
メソッドが引いてきた時にアウトとそういうことっぽい。
つまりはeval
メソッド実行時にunshredなREnvが存在すること自体はおかしくないので、もしunshredなら無視するように修正した。
はーこれに二週間かっかったけど勉強になった。
スタックが深くなると起こるバグはほかにもある気がするので、いつかまたハマったら思い出してみよう。
https://github.com/mruby/mruby/pull/3207
これもruby/spec/languageを走らせて遭遇した。
$ lldb mruby/bin/mruby (lldb) run mspec/bin/mspec-run spec/language/variables_spec.rb ... * thread #1: tid = 0x1acaab, 0x00000001000023ff mruby`mrb_ary_concat(mrb=0x0000000100202ad0, self=mrb_value @ 0x00007fff5fbfd3a0, other=mrb_value @ 0x00007fff5fbfd390) + 47 at array.c:273, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x28) frame #0: 0x00000001000023ff mruby`mrb_ary_concat(mrb=0x0000000100202ad0, self=mrb_value @ 0x00007fff5fbfd3a0, other=mrb_value @ 0x00007fff5fbfd390) + 47 at array.c:273 270 { 271 struct RArray *a2 = mrb_ary_ptr(other); 272 -> 273 ary_concat(mrb, mrb_ary_ptr(self), a2->ptr, a2->len); 274 } 275 276 static mrb_value (lldb) up frame #1: 0x00000001000437fa mruby`mrb_vm_exec(mrb=0x0000000100300390, proc=0x00000001008460f0, pc=0x000000010070ccf0) + 25562 at vm.c:2122 2119 2120 CASE(OP_ARYCAT) { 2121 /* A B mrb_ary_concat(R(A),R(B)) */ -> 2122 mrb_ary_concat(mrb, regs[GETARG_A(i)], 2123 mrb_ary_splat(mrb, regs[GETARG_B(i)])); 2124 ARENA_RESTORE(mrb, ai); 2125 NEXT; (lldb) up frame #2: 0x000000010003d407 mruby`mrb_vm_run(mrb=0x0000000100300390, proc=0x00000001008321d0, self=mrb_value @ 0x00007fff5fbfe070, stack_keep=0) + 135 at vm.c:759 756 } 757 stack_extend(mrb, irep->nregs, stack_keep); 758 mrb->c->stack[0] = self; -> 759 return mrb_vm_exec(mrb, proc, irep->iseq); 760 } 761 762 MRB_API mrb_value
mrb_ary_concat
での引数other
がnil
になっているので、nil
をarrayとして扱おうとして落ちている。再現率100%だ。やった。
OP_ARYCAT
というvm命令でおきていて、mrb_ary_splat
という関数がnil
を返しているようだ。
Rubyでsplatと言えば、*
での展開するヤツのことだ。
a = *nil #=> []
a = *'a' #=> ["a"]
a = *1 #=> [1]
a, b, c = *[1,2,3]; a #=> 1
さて、次の場合はどうなるか。
o = Object.new
a = *o
答えはStringやIntegerと同じく、自身を[]
で囲む。
o = Object.new a = *o # => [#<Object:0x007fea4315bc08>]
実はこのsplatはto_a
メソッドがなければ単に[]
で囲んで、to_a
があればそれを呼び出すようになっている。
o = Object.new def o.to_a ['hi'] end a = *o #=> ["hi"]
ここから更に細かいが、CRubyでは、to_aメソッドを読んで、nil
ならto_a
メソッドがなかった時と同じく単に[]
で囲む。
nil
じゃなければArray#concat
と同じことをする。くっつけるのは他の変数達。
a = *1, *'', *o => [1, "", "hi"]
コードは多分この辺
https://github.com/ruby/ruby/blob/d432af3df7ffa3fb2666674f70dab685e73de374/insns.def#L491-L513
これがmrubyでは実装されておらず、splatは単にto_a
の結果を返しているだけだった。
するとto_a
メソッドがarray以外を返すと、mrb_ary_concat
メソッドでarrayとして処理しようとしてバグとなる。
ここではCRubyと同じ動きになるように、mrb_ary_splat
を修正した。
CRubyの挙動にも詳しくなれてmrubyのバグも直って一石二鳥!
このブログ自体も時間をかけて作成されたため、途中で口調が変わっている。
おしまい。