Backport #8144: test_segv_test(TestRubyOptions) test failure

• Status: Rejected
• Assignee: naruse (Yui NARUSE)

[vo.x (Vit Ondruch)]

=begin
After doing several successful builds [1], next build crashed suddenly with:

test_segv_test(TestRubyOptions) [/builddir/build/BUILD/ruby-2.0.0-p0/test/ruby/test_rubyoptions.rb:513]:
Expected /#<Bogus:/ to match "-e:3: [BUG] Segmentation fault\nruby 2.0.0p0 (2013-02-24) [i386-linux]\n\n-- Control frame information -----------------------------------------------\nc:0003 p:---- s:0009 e:000008 CFUNC :kill\nc:0002 p:0041 s:0004 E:001ffc EVAL -e:3 [FINISH]\nc:0001 p:0000 s:0002 E:001d24 TOP [FINISH]\n\n-e:3:in <main>'\n-e:3:in kill'\n\n-- C level backtrace information -------------------------------------------\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x175cc9) [0x519cc9] vm_dump.c:647\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x54aef) [0x3f8aef] error.c:283\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_bug+0x41) [0x3f8f01] error.c:302\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x10700d) [0x4ab00d] signal.c:649\n[0xd84410]\n[0xd84430]\n/lib/libc.so.6(kill+0x16) [0x8dcab6]\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_f_kill+0x66) [0x4abaa6] signal.c:424\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x15ad6f) [0x4fed6f] vm_insnhelper.c:1294\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x15f7d9) [0x5037d9] vm_insnhelper.c:1438\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x170eaf) [0x514eaf] vm_insnhelper.c:1528\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x16365c) [0x50765c] insns.def:1017\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x1691d4) [0x50d1d4] vm.c:1175\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_iseq_eval_main+0x8c) [0x50f11c] vm.c:1423\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x57ccc) [0x3fbccc] eval.c:250\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(ruby_exec_node+0x25) [0x3fd535] eval.c:315\n/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(ruby_run_node+0x31) [0x3feff1] eval.c:307\n/builddir/build/BUILD/ruby-2.0.0-p0/ruby() [0x80486b9] main.c:36\n/lib/libc.so.6(__libc_start_main+0xf3) [0x8c7963]\n/builddir/build/BUILD/ruby-2.0.0-p0/ruby() [0x80486e1] main.c:38\n\n-- Other runtime information -----------------------------------------------\n\n* Loaded script: -e\n\n* Loaded features:\n\n".

In readable form:

test_segv_test(TestRubyOptions) [/builddir/build/BUILD/ruby-2.0.0-p0/test/ruby/test_rubyoptions.rb:513]:
Expected /#<Bogus:/ to match "-e:3: [BUG] Segmentation fault
ruby 2.0.0p0 (2013-02-24) [i386-linux]

-- Control frame information -----------------------------------------------
c:0003 p:---- s:0009 e:000008 CFUNC :kill
c:0002 p:0041 s:0004 E:001ffc EVAL -e:3 [FINISH]
c:0001 p:0000 s:0002 E:001d24 TOP [FINISH]

-e:3:in <main>' -e:3:in kill'

-- C level backtrace information -------------------------------------------
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x175cc9) [0x519cc9] vm_dump.c:647
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x54aef) [0x3f8aef] error.c:283
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_bug+0x41) [0x3f8f01] error.c:302
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x10700d) [0x4ab00d] signal.c:649
[0xd84410]
[0xd84430]
/lib/libc.so.6(kill+0x16) [0x8dcab6]
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_f_kill+0x66) [0x4abaa6] signal.c:424
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x15ad6f) [0x4fed6f] vm_insnhelper.c:1294
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x15f7d9) [0x5037d9] vm_insnhelper.c:1438
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x170eaf) [0x514eaf] vm_insnhelper.c:1528
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x16365c) [0x50765c] insns.def:1017
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x1691d4) [0x50d1d4] vm.c:1175
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(rb_iseq_eval_main+0x8c) [0x50f11c] vm.c:1423
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(+0x57ccc) [0x3fbccc] eval.c:250
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(ruby_exec_node+0x25) [0x3fd535] eval.c:315
/builddir/build/BUILD/ruby-2.0.0-p0/libruby.so.2.0.0(ruby_run_node+0x31) [0x3feff1] eval.c:307
/builddir/build/BUILD/ruby-2.0.0-p0/ruby() [0x80486b9] main.c:36
/lib/libc.so.6(__libc_start_main+0xf3) [0x8c7963]
/builddir/build/BUILD/ruby-2.0.0-p0/ruby() [0x80486e1] main.c:38

-- Other runtime information -----------------------------------------------

• Loaded script: -e

• Loaded features:

".

[1] https://bugs.ruby-lang.org/issues/7521#note-7
=end

[naruse (Yui NARUSE)]

I also experienced a similar failure on Linux i686 various distribution.
http://www.rubyist.net/~akr/chkbuild/debian/ruby-trunk/log/20130321T151200Z.diff.html.gz
http://c5632.rubyci.org/~chkbuild/ruby-trunk/log/20130321T030302Z.diff.html.gz
http://u32.rubyci.org/~chkbuild/ruby-trunk/log/20130319T230301Z.diff.html.gz

On this debian squeeze it always happen, but on CentOS 5.8/Ubuntu 10.04 it is at random.

My some inspection it seems because fprintf in rb_dump_backtrace_with_lines.
It is called from signal handler and fprintf is async signal unsafe.
This fprintf seems to break some memory value for example rb_cString.
But I doubt this really caused by this...

Anyway on debian squeeze, following patch fixed this.
Could you try this?

diff --git a/addr2line.c b/addr2line.c
index c0fad49..fc12b97 100644
--- a/addr2line.c
+++ b/addr2line.c
@@ -617,21 +617,25 @@ rb_dump_backtrace_with_lines(int num_traces, void **trace, char *syms)
/ fprintf may not be async-signal safe */
for (i = 0; i < num_traces; i++) {
line_info_t *line = &lines[i];

•   #define BUFLEN 256
  

•   char buf[BUFLEN];
  

•   int n;
  
    if (line->line > 0) {
        if (line->filename) {
            if (line->dirname && line->dirname[0]) {
  

•               fprintf(stderr, "%s %s/%s:%d\n", syms[i], line->dirname, line->filename, line->l
  

•               n = snprintf(buf, BUFLEN, "%s %s/%s:%d\n", syms[i], line->dirname, line->filenam
            }
            else {
  

•               fprintf(stderr, "%s %s:%d\n", syms[i], line->filename, line->line);
  

•               n = snprintf(buf, BUFLEN, "%s %s:%d\n", syms[i], line->filename, line->line);
            }
        } else {
  

•           fprintf(stderr, "%s ???:%d\n", syms[i], line->line);
  

•           n = snprintf(buf, BUFLEN, "%s ???:%d\n", syms[i], line->line);
        }
    } else {
  

•       fprintf(stderr, "%s\n", syms[i]);
  

•       n = snprintf(buf, BUFLEN, "%s\n", syms[i]);
    }
  

•   n = write(2, buf, n);
  

  }

  for (i = 0; i < num_traces; i++) {

[vo.x (Vit Ondruch)]

Thank you Yui. I could try it, but I am afraid I don't know how to recognize that it works for sure, due to its random nature :/

[naruse (Yui NARUSE)]

vo.x (Vit Ondruch) wrote:

Thank you Yui. I could try it, but I am afraid I don't know how to recognize that it works for sure, due to its random nature :/

Try below:

while make TESTS='-vn test_segv_test ruby/test_rubyoptions.rb' test-all;do :;done

[kosaki (Motohiro KOSAKI)]

My some inspection it seems because fprintf in rb_dump_backtrace_with_lines.
It is called from signal handler and fprintf is async signal unsafe.
This fprintf seems to break some memory value for example rb_cString.
But I doubt this really caused by this...

I really doubt it.
rb_dump_backtrace_with_lines() is only called from SEGV handler. but SEGV itself shouldn't be happen.
Moreover, I wonder why kill() in libc makes SEGV, not from ruby code.

[kosaki (Motohiro KOSAKI)]

I really doubt it.
rb_dump_backtrace_with_lines() is only called from SEGV handler. but SEGV itself shouldn't be happen.
Moreover, I wonder why kill() in libc makes SEGV, not from ruby code.

Sorry, I was confusion. It was test_segv_test. so, SEGV is not wrong.

[vo.x (Vit Ondruch)]

naruse (Yui NARUSE) wrote:

Try below:

while make TESTS='-vn test_segv_test ruby/test_rubyoptions.rb' test-all;do :;done

I gave it try, running without the patch for 2 hours and no luck to reproduce the original issue on my local machine, therefore there is no point to try the patch. Sorry :/

[naruse (Yui NARUSE)]

• Status changed from Open to Closed
• % Done changed from 0 to 100

This issue was solved with changeset r39887.
Vit, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

---

• addr2line.c (kprintf): added from FreeBSD libstand's printf.
  this is consided as async signal safe function.

• addr2line.c (rb_dump_backtrace_with_lines): use kfprintf.
  [Bug #8144] [ruby-core:53632]

[nagachika (Tomoyuki Chikanaga)]

• Tracker changed from Bug to Backport
• Project changed from Ruby master to Backport200
• Status changed from Closed to Assigned
• Assignee set to nagachika (Tomoyuki Chikanaga)
• Priority changed from Normal to 5

backport r39887 and r39921.
r40161 should be backported at the same time for #8227.

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Assigned to Closed

This issue was solved with changeset r40253.
Vit, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

---

merge revision(s) 39866,39887,39921,40161,40170: [Backport #8144] [Backport #8227]

* addr2line.c (rb_dump_backtrace_with_lines): output line at once.

* addr2line.c (kprintf): added from FreeBSD libstand's printf.
  this is consided as async signal safe function.

* addr2line.c (rb_dump_backtrace_with_lines): use kfprintf.
  [Bug #8144] [ruby-core:53632]

* addr2line.c (putce): suppress unused return value warning.

* addr2line.c: quad_t and u_quad_t is not available on Solaris.
  __inline is not available with old compilers on Solaris.
  [ruby-dev:47229] [Bug #8227]

* addr2line.c: use more generic type:
  * u_char -> unsigned char
  * u_short -> unsigned short
  * u_int -> unsigned int
  * u_long -> unsigned long
  * quad_t -> int64_t
  * u_quad_t -> uint64_t

* addr2line.c (imax): inline is defined by configure.

[vo.x (Vit Ondruch)]

• Status changed from Closed to Open
• Assignee changed from nagachika (Tomoyuki Chikanaga) to naruse (Yui NARUSE)
• Priority changed from 5 to Normal
• % Done changed from 100 to 0

=begin
Unfortunately, I met this issue today again, so the applied medicine was not enough it seems:

7. Failure:
   test_segv_test(TestRubyOptions) [/builddir/build/BUILD/ruby-2.0.0-p247/test/ruby/test_rubyoptions.rb:513]:
   Expected /#<Bogus:/ to match "-e:3: [BUG] Segmentation fault\nruby 2.0.0p247 (2013-06-27) [i386-linux]\n\n-- Control frame information -----------------------------------------------\nc:0003 p:---- s:0009 e:000008 CFUNC :kill\nc:0002 p:0041 s:0004 E:0008cc EVAL -e:3 [FINISH]\nc:0001 p:0000 s:0002 E:001cac TOP [FINISH]\n\n-e:3:in <main>'\n-e:3:in kill'\n\n-- C level backtrace information -------------------------------------------\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x176968) [0xf07968] vm_dump.c:647\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x5826d) [0xde926d] error.c:283\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(rb_bug+0x40) [0xde9680] error.c:302\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x108b4d) [0xe99b4d] signal.c:672\n[0x2e4410]\n[0x2e4430]\n/lib/libc.so.6(kill+0x16) [0x313c46]\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(rb_f_kill+0x5e) [0xe9a59e] signal.c:424\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x15b60e) [0xeec60e] vm_insnhelper.c:1325\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x160013) [0xef1013] vm_insnhelper.c:1469\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x171cf7) [0xf02cf7] vm_insnhelper.c:1559\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x164625) [0xef5625] insns.def:1017\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x169d96) [0xefad96] vm.c:1201\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(rb_iseq_eval_main+0x8b) [0xefcd2b] vm.c:1449\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(+0x5b3cc) [0xdec3cc] eval.c:250\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(ruby_exec_node+0x24) [0xdedbd4] eval.c:315\n/builddir/build/BUILD/ruby-2.0.0-p247/libruby.so.2.0.0(ruby_run_node+0x30) [0xdef6b0] eval.c:307\n/builddir/build/BUILD/ruby-2.0.0-p247/ruby() [0x80486b8] main.c:36\n/lib/libc.so.6(__libc_start_main+0xf3) [0x2fe933]\n/builddir/build/BUILD/ruby-2.0.0-p247/ruby() [0x80486e1] main.c:38\n\n-- Other runtime information -----------------------------------------------\n\n* Loaded script: -e\n\n* Loaded features:\n\n".
   13262 tests, 2234484 assertions, 1 failures, 0 errors, 34 skips
   ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-linux]
   make: *** [yes-test-all] Error 1
   =end

[naruse (Yui NARUSE)]

• Status changed from Open to Rejected