Bug #3371: test-all aborted on amd64 lenny

• Status: Closed
• Assignee: tenderlovemaking (Aaron Patterson)
• Target version: 1.9.2
• ruby -v: ruby 1.9.2dev (2010-05-07 trunk 27649) [x86_64-linux]

[znz (Kazuhiro NISHIYAMA)]

=begin
amd64のlennyで
http://chkbuild.n-z.jp/ruby/debian-amd64/ruby-trunk/log/20100507T073828.diff.txt.gz
のあたりから test-all がすべてのテストを実行後、 Aborted (core dumped) になって結果が表示されません。
=end

[mame (Yusuke Endoh)]

遠藤です。

gdb のバックトレースなどは見えないでしょうか。

--
Yusuke Endoh [e-mail]

[znz (Kazuhiro NISHIYAMA)]

http://chkbuild.n-z.jp/ruby/debian-amd64/ruby-trunk/log/20100607T073937.log.txt.gz
のcoreで調べてみると finalizer の実行で落ちているようですが、調べ方がよくわかりませんでした。
(gc.c:2773 は run_final の中で finalize_list の中じゃないとか。)

% pwd
/home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby
% sudo file core
core: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from './ruby -rpurelib.rb ./test/runner.rb -v'
% sudo -u chkbuild gdb ./ruby core
GNU gdb 6.8-debian
Copyright (C) 2008 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-linux-gnu"...

warning: Can't read pathname for load map: Input/output error.
Reading symbols from /lib/libpthread.so.0...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib/librt.so.1...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libm.so.6...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux-x86-64.so.2...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/enc/encdb.so...done.
Loaded symbols for /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/enc/encdb.so
Reading symbols from /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/enc/trans/transdb.so...done.
Loaded symbols for /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/enc/trans/transdb.so
Reading symbols from /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/stringio.so...done.
Loaded symbols for /home/chkbuild/tmp/build/ruby-trunk/20100607T073937/ruby/.ext/x86_64-linux/stringio.so
(略)
Reading symbols from /usr/lib/gconv/SJIS.so...done.
Loaded symbols for /usr/lib/gconv/SJIS.so
Core was generated by `./ruby -rpurelib.rb ./test/runner.rb -v'.
Program terminated with signal 6, Aborted.
[New process 15073]
#0  0x00007f7f818d1ed5 in raise () from /lib/libc.so.6
(gdb) bt
#0  0x00007f7f818d1ed5 in raise () from /lib/libc.so.6
#1  0x00007f7f818d33f3 in abort () from /lib/libc.so.6
#2  0x00007f7f7dd60895 in ffi_closure_free () from /usr/lib/libffi.so.5
#3  0x00007f7f7df6855d in dealloc (ptr=<value optimized out>) at closure.c:18
#4  0x00000000004228b3 in finalize_list (objspace=0x7e4b90, p=0x63be920)
    at gc.c:2773
#5  0x0000000000422c1f in rb_objspace_call_finalizer (objspace=0x7e4b90)
    at gc.c:2912
#6  0x000000000041cb1f in ruby_cleanup (ex=0) at eval.c:161
#7  0x000000000041ccc5 in ruby_run_node (n=0x80fed0) at eval.c:254
#8  0x0000000000419cdf in main (argc=4, argv=0x7fffffffd1c8) at main.c:35
(gdb) up 4
#4  0x00000000004228b3 in finalize_list (objspace=0x7e4b90, p=0x63be920)
    at gc.c:2773
2773            (*free_func)(DATA_PTR(obj));
(gdb) rp obj
No symbol "obj" in current context.
(gdb) p obj
No symbol "obj" in current context.
(gdb) info args
objspace = (rb_objspace_t *) 0x7e4b90
p = (RVALUE *) 0x63be920
(gdb) list
2768        }
2769        else {
2770            free_func = RDATA(obj)->dfree;
2771        }
2772        if (free_func) {
2773            (*free_func)(DATA_PTR(obj));
2774        }
2775
2776        if (finalizer_table &&
2777            st_delete(finalizer_table, (st_data_t*)&obj, &table)) {
(gdb) p free_func
Attempt to use a type name as an expression
(gdb) p obj
No symbol "obj" in current context.
(gdb) rp objspace
T_TRUE: $1 = (struct RBasic *) 0x7e4b90
(gdb) rp p
T_ZOMBIE: $2 = (struct RData *) 0x63be920
(gdb)

[znz (Kazuhiro NISHIYAMA)]

• Assignee set to tenderlovemaking (Aaron Patterson)

全部実行しなくても dl fiddle gdbm の3ディレクトリだけでも再現しました。

% ./miniruby -v
ruby 1.9.3dev (2010-06-10 trunk 28243) [x86_64-linux]
% make test-all TESTS="-v dl fiddle gdbm" RUNRUBYOPT='--debug'
./miniruby -I../lib -I.ext/common -I./- -r../ext/purelib.rb  ../tool/runruby.rb --extout=.ext --debug -- "../test/runner.rb" -v dl fiddle gdbm
GNU gdb 6.8-debian
Copyright (C) 2008 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-linux-gnu"...
(gdb) r
Starting program: .../ruby -rpurelib.rb ../test/runner.rb -v dl fiddle gdbm
[Thread debugging using libthread_db enabled]
[New Thread 0x2b7390ca02c0 (LWP 4588)]
[New Thread 0x40003950 (LWP 4591)]
Loaded suite ../test/runner
Started
DL::TestBase#test_empty: 0.00 s: .
DL::TestCFunc#test_empty: 0.00 s: .
DL::TestCFunc#test_inspect: 0.00 s: .
DL::TestCFunc#test_inspect_is_tainted: 0.00 s: .
DL::TestCFunc#test_last_error: [New Thread 0x40084950 (LWP 4592)]
0.01 s: .
DL::TestCFunc#test_name_should_be_duped: 0.00 s: .
DL::TestCFunc#test_new_ptr: 0.00 s: .
DL::TestCFunc#test_new_ptr_type_name: 0.00 s: .
DL::TestCFunc#test_ptr: 0.00 s: .
DL::TestCFunc#test_ptr=: 0.00 s: .
DL::TestCFunc#test_set_calltype: 0.00 s: .
DL::TestCFunc#test_to_i: 0.00 s: .
DL::TestCFunc#test_to_s: 0.00 s: .
DL::TestCParser#test_empty: 0.00 s: .
DL::TestCParser#test_uint_ctype: 0.00 s: .
DL::TestCPtr#test_aref_aset: 0.00 s: .
DL::TestCPtr#test_cmp: 0.00 s: .
DL::TestCPtr#test_cptr_to_int: 0.00 s: .
DL::TestCPtr#test_empty: 0.00 s: .
DL::TestCPtr#test_equals: 0.00 s: .
DL::TestCPtr#test_free: 0.00 s: .
DL::TestCPtr#test_free=: [Thread 0x40003950 (LWP 4591) exited]
[Thread 0x40084950 (LWP 4592) exited]
[New Thread 0x40003950 (LWP 4594)]
0.02 s: .
DL::TestCPtr#test_inspect: 0.00 s: .
DL::TestCPtr#test_malloc_free_func: 0.00 s: .
DL::TestCPtr#test_malloc_free_func_int: 0.00 s: .
DL::TestCPtr#test_minus: 0.00 s: .
DL::TestCPtr#test_not_equals: 0.00 s: .
DL::TestCPtr#test_null?: 0.00 s: .
DL::TestCPtr#test_plus: 0.00 s: .
DL::TestCPtr#test_ref_ptr: 0.00 s: .
DL::TestCPtr#test_size: 0.00 s: .
DL::TestCPtr#test_size=: 0.00 s: .
DL::TestCPtr#test_to_ptr_io: 0.00 s: .
DL::TestCPtr#test_to_ptr_string: 0.00 s: .
DL::TestCPtr#test_to_ptr_with_num: 0.00 s: .
DL::TestCPtr#test_to_ptr_with_ptr: 0.00 s: .
DL::TestCPtr#test_to_s: 0.00 s: .
DL::TestCPtr#test_to_str: 0.00 s: .
DL::TestCPtr#test_to_value: 0.00 s: .
DL::TestCallback#test_call_callback: 0.00 s: .
DL::TestCallback#test_callback_return_arbitrary: 0.00 s: .
DL::TestCallback#test_callback_return_value: 0.00 s: .
DL::TestCallback#test_callback_with_string: 0.00 s: .
DL::TestCallback#test_empty: 0.00 s: .
DL::TestCallback#test_remove_callback: 0.00 s: .
DL::TestCallback#test_remove_callback_failed: 0.00 s: .
DL::TestDL#test_call_double: 0.00 s: .
DL::TestDL#test_call_int: 0.00 s: .
DL::TestDL#test_call_long: 0.00 s: .
DL::TestDL#test_callback: 0.00 s: .
DL::TestDL#test_dlwrap: 0.00 s: .
DL::TestDL#test_empty: 0.00 s: .
DL::TestDL#test_free_secure: [New Thread 0x40084950 (LWP 4596)]
[Thread 0x40084950 (LWP 4596) exited]
0.00 s: .
DL::TestDL#test_malloc: 0.00 s: .
DL::TestDL#test_malloc_security: [New Thread 0x40084950 (LWP 4597)]
[Thread 0x40084950 (LWP 4597) exited]
0.00 s: .
DL::TestDL#test_realloc: 0.00 s: .
DL::TestDL#test_realloc_secure: [New Thread 0x40084950 (LWP 4598)]
[Thread 0x40084950 (LWP 4598) exited]
0.00 s: .
DL::TestDL#test_sin: 0.00 s: .
DL::TestDL#test_strcpy: 0.00 s: .
DL::TestDL#test_strlen: 0.00 s: .
DL::TestFunc#test_atof: 0.00 s: .
DL::TestFunc#test_empty: 0.00 s: .
DL::TestFunc#test_isdigit: 0.00 s: .
DL::TestFunc#test_name: 0.00 s: .
DL::TestFunc#test_qsort1: 0.00 s: .
DL::TestFunc#test_qsort2: 0.00 s: .
DL::TestFunc#test_random: 0.00 s: .
DL::TestFunc#test_sin: 0.00 s: .
DL::TestFunc#test_sinf: 0.00 s: .
DL::TestFunc#test_strcpy: 0.00 s: .
DL::TestFunc#test_strtod: 0.00 s: .
DL::TestFunc#test_to_i: 0.00 s: .
DL::TestHandle#test_DEFAULT: 0.00 s: .
DL::TestHandle#test_NEXT: 0.00 s: .
DL::TestHandle#test_disable_close: 0.00 s: .
DL::TestHandle#test_dlopen_returns_handle: 0.00 s: .
DL::TestHandle#test_dlopen_safe: [New Thread 0x40084950 (LWP 4599)]
[Thread 0x40084950 (LWP 4599) exited]
0.01 s: .
DL::TestHandle#test_empty: 0.00 s: .
DL::TestHandle#test_enable_close: 0.00 s: .
DL::TestHandle#test_handle_close: 0.00 s: .
DL::TestHandle#test_handle_close_twice: 0.00 s: .
DL::TestHandle#test_initialize_flags: 0.00 s: .
DL::TestHandle#test_initialize_noargs: 0.00 s: .
DL::TestHandle#test_initialize_safe: [New Thread 0x40084950 (LWP 4600)]
0.01 s: .
DL::TestHandle#test_static_sym: 0.00 s: .
DL::TestHandle#test_static_sym_secure: [Thread 0x40084950 (LWP 4600) exited]
[New Thread 0x40105950 (LWP 4601)]
[Thread 0x40105950 (LWP 4601) exited]
0.02 s: .
DL::TestHandle#test_static_sym_unknown: 0.00 s: .
DL::TestHandle#test_sym: 0.00 s: .
DL::TestHandle#test_sym_closed_handle: 0.00 s: .
DL::TestHandle#test_sym_secure: [New Thread 0x40105950 (LWP 4602)]
0.00 s: .
DL::TestHandle#test_sym_unknown: 0.00 s: .
DL::TestHandle#test_sym_with_bad_args: 0.00 s: .
DL::TestHandle#test_to_i: 0.00 s: .
DL::TestImport#test_atof: 0.00 s: .
DL::TestImport#test_carried_function: 0.00 s: .
DL::TestImport#test_empty: 0.00 s: .
DL::TestImport#test_gettimeofday: 0.00 s: .
DL::TestImport#test_io: 0.00 s: .
DL::TestImport#test_isdigit: 0.00 s: .
DL::TestImport#test_malloc: 0.00 s: .
DL::TestImport#test_qsort: 0.00 s: .
DL::TestImport#test_sizeof: 0.00 s: .
DL::TestImport#test_strcpy: 0.00 s: .
DL::TestImport#test_strtod: 0.00 s: .
DL::TestImport#test_struct: 0.00 s: .
DL::TestImport#test_unsigned_result: 0.00 s: .
DL::TestImport#test_value: 0.00 s: .
DL::TestWin32#test_empty: 0.00 s: .
Fiddle::TestClosure#test_returner: 0.00 s: .
Fiddle::TestClosure#test_call: 0.00 s: .
Fiddle::TestClosure#test_argument_errors: 0.00 s: .
Fiddle::TestClosure#test_block_caller: 0.00 s: .
Fiddle::TestFunction#test_strcpy: 0.00 s: .
Fiddle::TestFunction#test_argument_errors: 0.00 s: .
Fiddle::TestFunction#test_default_abi: 0.00 s: .
Fiddle::TestFunction#test_call: 0.00 s: .
Fiddle::TestFunction#test_last_error: 0.00 s: .
Fiddle::TestFunction#test_argument_count: 0.00 s: .
TestFiddle#test_constants_match: 0.00 s: .
TestGDBM#test_aref: [Thread 0x40105950 (LWP 4602) exited]
0.01 s: .
TestGDBM#test_aset: 0.01 s: .
TestGDBM#test_cachesize=: 0.01 s: .
TestGDBM#test_clear: 0.01 s: .
TestGDBM#test_close: 0.01 s: .
TestGDBM#test_delete: 0.01 s: .
TestGDBM#test_delete_if: 0.01 s: .
TestGDBM#test_delete_with_block: 0.01 s: .
TestGDBM#test_each_key: 0.01 s: .
TestGDBM#test_each_pair: 0.01 s: .
TestGDBM#test_each_value: 0.01 s: .
TestGDBM#test_empty?: 0.01 s: .
TestGDBM#test_fastmode=: 0.00 s: .
TestGDBM#test_fetch: 0.01 s: .
TestGDBM#test_has_value?: 0.01 s: .
TestGDBM#test_haskey?: 0.01 s: .
TestGDBM#test_invert: 0.01 s: .
TestGDBM#test_key: 0.01 s: .
TestGDBM#test_keys: 0.01 s: .
TestGDBM#test_length: 0.01 s: .
TestGDBM#test_reject: 0.01 s: .
TestGDBM#test_reorganize: 0.03 s: .
TestGDBM#test_replace: 0.01 s: .
TestGDBM#test_s_new_has_no_block: 0.01 s: .
TestGDBM#test_s_open_3rd_arg: 0.01 s: .
TestGDBM#test_s_open_create_new: 0.01 s: .
TestGDBM#test_s_open_error: 0.01 s: .
TestGDBM#test_s_open_lock: [Thread 0x40003950 (LWP 4594) exited]
[New Thread 0x40003950 (LWP 4604)]
[Thread 0x40003950 (LWP 4604) exited]
[New Thread 0x40003950 (LWP 4607)]
2.03 s: .
TestGDBM#test_s_open_no_create: 0.01 s: .
TestGDBM#test_s_open_nolock: [Thread 0x40003950 (LWP 4607) exited]
[New Thread 0x40003950 (LWP 4610)]
[Thread 0x40003950 (LWP 4610) exited]
[New Thread 0x40003950 (LWP 4613)]
[Thread 0x40003950 (LWP 4613) exited]
[New Thread 0x40003950 (LWP 4616)]
4.03 s: .
TestGDBM#test_s_open_with_block: 0.01 s: .
TestGDBM#test_select_with_block: 0.01 s: .
TestGDBM#test_shift: 0.01 s: .
TestGDBM#test_sync: 0.01 s: .
TestGDBM#test_syncmode=: 0.00 s: .
TestGDBM#test_to_a: 0.01 s: .
TestGDBM#test_to_hash: 0.01 s: .
TestGDBM#test_update: 0.01 s: .
TestGDBM#test_values: 0.01 s: .
TestGDBM#test_values_at: 0.01 s: .
TestGDBM2#test_freeze: 0.00 s: .
TestGDBM2#test_newdb_open: 0.00 s: .
TestGDBM2#test_newdb_open_notexist: 0.00 s: .
TestGDBM2#test_reader_open: 0.00 s: .
TestGDBM2#test_reader_open_notexist: 0.00 s: .
TestGDBM2#test_wrcreat_open_notexist: 0.00 s: .
TestGDBM2#test_writer_open_notexist: 0.00 s: .

Finished in 6.435101 seconds.

166 tests, 1182 assertions, 0 failures, 0 errors, 0 skips

Test run options: --seed 51616 --verbose
[Thread 0x40003950 (LWP 4616) exited]

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x2b7390ca02c0 (LWP 4588)]
0x00002b739097ded5 in raise () from /lib/libc.so.6
(gdb) bt
#0  0x00002b739097ded5 in raise () from /lib/libc.so.6
#1  0x00002b739097f3f3 in abort () from /lib/libc.so.6
#2  0x00002aaaab2e3895 in ffi_closure_free () from /usr/lib/libffi.so.5
#3  0x00002aaaab0c9d65 in dealloc (ptr=0xd05000)
    at ../../../ext/fiddle/closure.c:18
#4  0x0000000000425902 in run_final (objspace=0x834810, obj=12689960)
    at ../gc.c:2773
#5  0x000000000042322f in finalize_list (objspace=0x834810, p=0xc1a228)
    at ../gc.c:1841
#6  0x0000000000425dd4 in rb_objspace_call_finalizer (objspace=0x834810)
    at ../gc.c:2912
#7  0x0000000000425ab2 in rb_gc_call_finalizer_at_exit () at ../gc.c:2842
#8  0x000000000041b238 in ruby_finalize_1 () at ../eval.c:111
#9  0x000000000041b46f in ruby_cleanup (ex=0) at ../eval.c:161
#10 0x000000000041b75c in ruby_run_node (n=0x863648) at ../eval.c:254
#11 0x0000000000419ecb in main (argc=7, argv=0x7fffffffc118) at ../main.c:35
(gdb)

[naruse (Yui NARUSE)]

This is because of libffi's bug.

It seems fixed in 3.0.5.

3.0.5 Apr-3-08
        Fix libffi.pc file.
  Fix #define ARM for IcedTea users.
  Fix x86 closure bug.

http://d.hatena.ne.jp/moriyoshi/20080322/1206220188

So we need some workaround.

[naruse (Yui NARUSE)]

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

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

[znz (Kazuhiro NISHIYAMA)]

r28300 の変更で Abort はしなくなりましたが、ext/fiddle/closure.c:dealloc だけではなく ext/fiddle/closure.c:allocate も変更する必要があるのではないでしょうか?