注

自分の頭の整理のためのエントリーです。よって超長い。

mruby-spec

以前、mrubyでruby/specを走らせるやつを書いたのですが、その後どうなったのかまとめてみます。

ksss9.hatenablog.com

成果

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倍に伸長される。

f:id:ksss9:20160909223450p:plain

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には気になるマクロがある。

https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/include/mruby/proc.h#L27-L28

そういえば問題は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 スタックを積み上げる操作。

f:id:ksss9:20160910181003p:plain

さらにヒントになったのが、blameしていてみつけたこのPR

github.com

この再現コードでいわゆる"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のバグも直って一石二鳥！

このブログ自体も時間をかけて作成されたため、途中で口調が変わっている。

おしまい。

スペクトラム

mruby-specの成果報告

注

mruby-spec

成果

https://github.com/mruby/mruby/pull/3204

https://github.com/mruby/mruby/pull/3206

https://github.com/mruby/mruby/pull/3207