SEGV探偵が往く
人は誰しも108つの夢を持つと言いますが、読者の皆さんにも探偵を夢見た人は多いことでしょう。実際問題として探偵業をやろうと思ったら地道な聞き込み＆張り込みの日々でしょうし、逆に派手な探偵業は陰謀＆殺人で恐ろしい。わたしも自分の命は大事ですからどうするか。そう、探偵ごっこをするわけですね。
というわけでSEGV探偵です。死ぬのはプロセスなので安心。Rubyを使っていればSEGVなんて見慣れたものですが、いざ捜査しようと思うと意外とその辺には転がっていないもの。（むかしはつかみ取り出来るくらいいたそうですよ）とはいえ今でもいわゆる「バグ鉱脈」みたいなものはありまして、その一つが「最新のコンパイラでビルドしてみる」です。
今日はGCCの開発版であるGCC8を試してみましょう。FreeBSDだとsudo pkg install lang/gcc8-develで簡単に入れられるのですが、他の環境だとちょっと大変かもしれません。さておきうちでは簡単なので入れてビルドしてmake testしてみます。
・・・はい、早速SEGVしました。
test_thread.rb ...................................FF.............
#1180 test_thread.rb:330:in `<top (required)>':
Fiber.new(&Object.method(:class_eval)).resume("foo")
#=> killed by SIGIOT (signal 6)
| [BUG] Segmentation fault at 0x0000000000000000
| ruby 2.5.0dev (2017-08-20 trunk 59626) [x86_64-linux]
|
| -- Control frame information -----------------------------------------------
| c:0003 p:---- s:0009 e:000008 CFUNC :class_eval
| c:0002 p:---- s:0006 e:000005 IFUNC
| c:0001 p:---- s:0003 e:000002 (none) [FINISH]
|
| -- Ruby level backtrace information ----------------------------------------
| bootstraptest.tmp.rb:0:in `class_eval'
|
| -- Machine register context ------------------------------------------------
| RIP: 0x000000000060a481 RBP: 0x00000000010a5630 RSP: 0x00007ff54468ea60
| RAX: 0x00007ff5446af010 RBX: 0x0000000000000001 RCX: 0x00007ff5446af010
| RDX: 0x0000000000000000 RDI: 0x00000000010e5730 RSI: 0x00000000010a5680
| R8: 0x0000000000000034 R9: 0x0000000000000001 R10: 0x000000000000101a
| R11: 0x0000000000000000 R12: 0x0000000000000000 R13: 0x0000000000000034
| R14: 0x00000000010e5730 R15: 0x00007ff54468ee48 EFL: 0x0000000000010202
|
| -- C level backtrace information -------------------------------------------
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_vm_bugreport+0x50d) [0x6157ad] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm_dump.c:671
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_bug_context+0xd8) [0x491e28] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/error.c:539
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(sigsegv+0x42) [0x588802] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/signal.c:930
| /lib/x86_64-linux-gnu/libpthread.so.0 [0x7ff544395390]
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(eval_string_with_cref+0xb1) [0x60a481] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm.c:505
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_mod_module_eval+0x10a) [0x60afca] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm_eval.c:1613
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(vm_call0_body.constprop.158+0x270) [0x60b610] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm_eval.c:86
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_vm_call+0x30) [0x60ba80] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm_eval.c:59
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(vm_yield_with_cfunc.isra.128+0x14d) [0x5fe39d] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm_insnhelper.c:2532
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_vm_invoke_proc+0x5c) [0x6094cc] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm.c:1167
| /home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(rb_fiber_start+0x11e) [0x47097e] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/cont.c:1344
| /lib/x86_64-linux-gnu/libc.so.6 [0x7ff54363f5d0]
|
…
RubyにはSEGVが発生した際にそれをキャッチしてCレベルでのバックトレースを表示する機能がついているので、いきなりCソースにたどり着くことが出来ます。上の4行はCバックトレース表示部分とシグナルトランポリンなので飛ばして、/home/ko1/ruby/build/trunk-test-gcc-trunk-np/miniruby(eval_string_with_cref+0xb1) [0x60a481] /home/ko1/ruby/src/trunk-test-gcc-trunk-np/vm.c:505が本題ですね。見てみましょう。
rb_control_frame_t * rb_vm_get_ruby_level_next_cfp(const rb_thread_t *th, const rb_control_frame_t *cfp) { while (!RUBY_VM_CONTROL_FRAME_STACK_OVERFLOW_P(th, cfp)) { if (VM_FRAME_RUBYFRAME_P(cfp)) { return (rb_control_frame_t *)cfp; } cfp = RUBY_VM_PREVIOUS_CONTROL_FRAME(cfp); } return 0; }
505行目はRUBY_VM_PREVIOUS_CONTROL_FRAME(cfp)ですが、マクロが一杯でよくわかりません。こういうときはMakefileを開いて、CFLAGSの行に-save-tempsを追加してビルドし直すとコンパイル中の一時ファイルが残ります。今回の場合vm.iが残っているはずです。見ると以下のような内容が得られます。
rb_control_frame_t * rb_vm_get_ruby_level_next_cfp(const rb_thread_t *th, const rb_control_frame_t *cfp) { while (!(!((void *)(((rb_control_frame_t *)((th)->ec.vm_stack + (th)->ec.vm_stack_size))) > (void *)((cfp))))) { if (VM_FRAME_RUBYFRAME_P(cfp)) { return (rb_control_frame_t *)cfp; } cfp = ((cfp)+1); } return 0; }
なお、VM_FRAME_RUBYFRAME_P()はマクロと見せかけて関数で、実質cfp->ep[0] & 0x80という内容です。
古いコンパイラならば動くのに最新のコンパイラでだけこけるという場合は、通常より高度になった最適化が原因です。ですので、コンパイラの最適化で壊れるような要素、具体的にはC標準において未定義な動作をつくコードや、冗長でコンパイラによって消されそうなコードを探すのですが……見当たりませんね……。仮にそのようなコードがあったなら、直してみてうまく動けば大勝利なのですが、今回はそうではなかったようです。
とすると、これはコンパイラ側の問題である可能性が高まってきますね。しかし、どのようにしてコンパイラの問題であることを示せば良いのでしょうか。この問いは私にとって未解決なのですが、とりあえず期待と異なる命令列が出力されていることを示すことにしましょう。これを示すにはいくつか方法があります。
通常、デバッグにおいては「期待する動作とはどんなものか」という非常に難しい問題があるのですが、今回の場合少し古いコンパイラの結果と比較することであるべき姿がどんなものか知ることが出来ます。
また、バグを見つけたときはまず再現出来るようにすることが重要ですが、これは既に達成されました。また、小さなRubyコードで再現出来るようにすることも重要ですが、これも達成出来ています。ここまで小さければgdbで実行してみましょう。
% gdb --args ./miniruby -e'Thread.new("foo", &Object.method(:class_eval)).join'
GNU gdb (GDB) 8.0 [GDB v8.0 for FreeBSD]
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-portbld-freebsd10.3".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./miniruby...done.
(gdb) r
Starting program: /tmp/ruby/miniruby -eThread.new\(\"foo\",\ \&Object.method\(:class_eval\)\).join
[New LWP 101479 of process 94182]
[New LWP 101478 of process 94182]
Thread 2 received signal SIGSEGV, Segmentation fault.
[Switching to LWP 101479 of process 94182]
0x000000000124c591 in rb_vm_get_ruby_level_next_cfp (cfp=0x805506000, th=<optimized out>)
at vm.c:505
505 cfp = RUBY_VM_PREVIOUS_CONTROL_FRAME(cfp);
まぁ、gdb上でも再現したのはよいことなのですが、本当はこのちょっと前でbreakしたいのです。これはLinuxだとReverse Debugという魔法で解決出来るのですが、FreeBSDではサポートされていないのでconditional breakpointを使います。よく考えた結果、b rb_vm_get_ruby_level_next_cfp if ruby_current_thread != ruby_current_vm->main_thread&&ruby_current_vm->main_threadでSEGV少し前に行けます。
そこからstepi（命令単位ステップ実行）を使ってとりあえず流し見します。すると、わりと狭い範囲をループしていることが分かります。まぁCのコードを見返してみれば当然なのですが。ではループしている範囲を逆アセンブルして見てみましょう
(gdb) disas 0x000000000124c591-61,+116 Dump of assembler code from 0x124c554 to 0x124c5c8: 0x000000000124c554 <eval_string_with_cref+116>: mov 0x60(%rsp),%rdx 0x000000000124c559 <eval_string_with_cref+121>: mov 0x28(%rdx),%rcx 0x000000000124c55d <eval_string_with_cref+125>: mov 0x20(%rdx),%rdx 0x000000000124c561 <eval_string_with_cref+129>: mov 0x30(%rax),%rax 0x000000000124c565 <eval_string_with_cref+133>: lea (%rdx,%rcx,8),%rcx 0x000000000124c569 <eval_string_with_cref+137>: cmp %rcx,%rax 0x000000000124c56c <eval_string_with_cref+140>: jae 0x124c59f <eval_string_with_cref+191> 0x000000000124c56e <eval_string_with_cref+142>: mov 0x20(%rax),%rdx 0x000000000124c572 <eval_string_with_cref+146>: testb $0x80,(%rdx) 0x000000000124c575 <eval_string_with_cref+149>: jne 0x124c589 <eval_string_with_cref+169> 0x000000000124c577 <eval_string_with_cref+151>: jmpq 0x124c6d8 <eval_string_with_cref+504> 0x000000000124c57c <eval_string_with_cref+156>: nopl 0x0(%rax) 0x000000000124c580 <eval_string_with_cref+160>: test %rdx,%rdx 0x000000000124c583 <eval_string_with_cref+163>: je 0x124c6d8 <eval_string_with_cref+504> 0x000000000124c589 <eval_string_with_cref+169>: add $0x30,%rax 0x000000000124c58d <eval_string_with_cref+173>: mov 0x20(%rax),%rdx => 0x000000000124c591 <eval_string_with_cref+177>: mov (%rdx),%rdx 0x000000000124c594 <eval_string_with_cref+180>: and $0x80,%edx 0x000000000124c59a <eval_string_with_cref+186>: cmp %rax,%rcx 0x000000000124c59d <eval_string_with_cref+189>: ja 0x124c580 <eval_string_with_cref+160> 0x000000000124c59f <eval_string_with_cref+191>: lea 0x306f5a(%rip),%rax # 0x1553500 <rb_eRuntimeError> 0x000000000124c5a6 <eval_string_with_cref+198>: lea 0x4a79b(%rip),%rsi # 0x1296d48 0x000000000124c5ad <eval_string_with_cref+205>: mov (%rax),%rdi 0x000000000124c5b0 <eval_string_with_cref+208>: xor %eax,%eax 0x000000000124c5b2 <eval_string_with_cref+210>: callq 0x10c4af0 <rb_raise> 0x000000000124c5b7 <eval_string_with_cref+215>: nopw 0x0(%rax,%rax,1) 0x000000000124c5c0 <eval_string_with_cref+224>: lea 0x2f3499(%rip),%rsi # 0x153fa60 <ruby_binding_data_type> 0x000000000124c5c7 <eval_string_with_cref+231>: mov %rax,%rdi
stepiによると、最初から走ってきた後、しばらく0x124c580と0x124c59dの間をループして、最後に0x124c591でSEGVしています。ここでの登場人物を紹介しておくと以下の通りです。
- rax:
cfp - rcx:
(th)->ec.vm_stack + (th)->ec.vm_stack_size - rdx:
cfp->eporcfp->ep[0]orcfp->ep[0] & 80
add $0x30,%rax が cfp+1に対応し、mov; mov; andがcfp->ep[0] & 80に対応するのですが、勘の言い方はもう気付かれたのではないでしょうか。cfpの妥当性、つまり確かにcfp-ep[0]にアクセス出来るというのは、(th)->ec.vm_stack + (th)->ec.vm_stack_size > cfpが真の時にだけ保証されています。しかし、この逆アセンブルではその分岐であるcmp %rax,%rcx; jaの前に、mov 0x20(%rax),%rdx; mov (%rdx),%rdxでcfp->epにアクセスしてしまっていますね。このような順番の入れ替えは許されていません。ですので、これこそが今回の直接の原因だったことが分かります。
というような話をまとめてバグレポートしたのがBug 81954 - gcc8 too aggressively reorders memory access beyond conditionです。これは結局はBug 81900 - [8 Regression] GCC trunk miscompiles Perl / __sigsetjmp issueのduplicateであり、報告の数日前に直っていたという残念な話でした。実際、GCC8をtrunkからビルドし直したところあっさり解決してしまいました。
今回は残念ながら犯人に自殺されてしまうような残念な幕切れとなってしまいました。しかし、この記事に書いたような、探偵七つ道具を使い、証拠を集め、SEGVを追い詰めていく過程は、SEGV探偵を志す皆さんにとって参考となるのではないでしょうか。なるといいですね。
このケースとは異なり、もしRuby側に問題があって、たった1行のパッチで問題を解決出来る、そんなケースに出会えたならば、あなたはきっとダークソウルやFF14などのとても難しいボスを倒せたときのような気持ちを体験出来ることでしょう。そう「誰だこんな難易度に調整しやがったやつは！ふざけんな！！」という気持ちですね。
この記事を読んだ皆さんが、明日からはSEGVを踏んでも「ククッ、事件のにおいがするぜ」とニヤリと笑えることを祈っています。
