[ruby-core:46366] Getting "exception reentered" with 1.9.2-p290

Hi everyone,

Me and my team mates have found an interesting problem with ruby 1.9.2. We
were converting from 1.8.7 when our cucumber tests started to fail at
random points, with "exception reentered" as the problem.

After some help from the IRC ruby-dev chat room, I've been able to obtain a
stack trace of the exception.

It looks to my eyes as if a read_nonblock is getting nothing from an IO and
then keeling over, but reentering the exception instead of dying gracefully.

Also, I should mention that this problem does not occur with ruby 1.9.3.
Our team does not have access to that ruby version in production, however.

I'm including the stack trace below. There is more to it, but I think this
is likely sufficient for now.

If someone can help to figure out more precisely how this problem is
triggered, and more importantly, how to navigate inside of gdb and the ruby
VM, I'd appreciate the knowledge.


Breakpoint 1, rb_threadptr_set_raised (th=0x105201b60) at thread.c:1412
1412		return 1;
(gdb) bt
#0  rb_threadptr_set_raised (th=0x105201b60) at thread.c:1412
#1  0x0000000104eaaba4 in setup_exception (th=0x105201b60, tag=6,
mesg=140397377046000) at eval.c:434
#2  0x0000000104eaac85 in rb_longjmp (tag=6, mesg=140397377046000) at
eval.c:451#3  0x0000000104eaace7 in rb_exc_raise (mesg=Could not find
the frame base for "rb_exc_raise".
) at eval.c:464
#4  0x0000000104ea7a2c in rb_raise (exc=Could not find the frame base
for "rb_raise".
) at error.c:1475
#5  0x0000000104ec05ab in id2ref (obj=140397137802680,
objid=140397325663161) at gc.c:2799
#6  0x0000000104eab246 in rb_rescue2 (b_proc=0x105bb3680
<id2ref_unprotected>, data1=140397325663161, r_proc=0x105bb3640
<id2ref_error>, data2=0) at eval.c:647
#7  0x0000000104eab4fe in rb_rescue (b_proc=0x105bb3680
<id2ref_unprotected>, data1=140397325663161, r_proc=0x105bb3640
<id2ref_error>, data2=0) at eval.c:699
#8  0x0000000105bb3fe1 in id2ref [inlined] () at
/Users/gducharme/.rvm/gems/ruby-1.9.2-p290/gems/ruby-debug-base19-0.11.25/ext/ruby_debug/ruby_debug.c:186
#9  0x0000000105bb3fe1 in threads_table_check_i (key=<value
temporarily unavailable, due to optimizations>, value=<value
temporarily unavailable, due to optimizations>, dummy=<value
temporarily unavailable, due to optimizations>) at ruby_debug.c:310
#10 0x0000000104f70c84 in st_foreach (table=0x7fb0cba93210,
func=0x105bb3fc0 <threads_table_check_i>, arg=0) at st.c:747
#11 0x0000000105bb631d in debug_event_hook (event=96183280,
data=<value temporarily unavailable, due to optimizations>,
self=140397325250640, mid=0, klass=0) at ruby_debug.c:328
#12 0x0000000104fef5dc in exec_event_hooks (hook=0x7fb0cb98cc70,
flag=128, self=140397325250640, id=0, klass=0) at thread.c:3795
#13 0x0000000104fef57c in rb_threadptr_exec_event_hooks
(th=0x105201b60, flag=128, self=140397325250640, id=0, klass=0) at
thread.c:3815
#14 0x0000000104eaac4e in setup_exception (th=0x105201b60, tag=6,
mesg=140397377050280) at eval.c:443
#15 0x0000000104eaac85 in rb_longjmp (tag=6, mesg=140397377050280) at eval.c:451
#16 0x0000000104eaace7 in rb_exc_raise (mesg=Could not find the frame
base for "rb_exc_raise".
) at eval.c:464
#17 0x0000000104ea7df6 in rb_mod_sys_fail (mod=Could not find the
frame base for "rb_mod_sys_fail".
) at error.c:1547
#18 0x0000000104ecb51b in io_getpartial (argc=1, argv=0x105300c80,
io=140397325250640, nonblock=1) at io.c:1886
#19 0x0000000104ecb60d in io_read_nonblock (argc=1, argv=0x105300c80,
io=140397325250640) at io.c:2021
#20 0x0000000104fdc5ec in call_cfunc (func=0x104ecb5e5
<io_read_nonblock>, recv=140397325250640, len=-1, argc=1,
argv=0x105300c80) at vm_insnhelper.c:315
#21 0x0000000104fdc455 in vm_call_cfunc (th=0x105201b60,
reg_cfp=0x1053fdcf0, num=1, recv=140397325250640, blockptr=0x0,
me=0x105251cd0) at vm_insnhelper.c:402
#22 0x0000000104fdb63c in vm_call_method (th=0x105201b60,
cfp=0x1053fdcf0, num=1, blockptr=0x0, flag=0, id=6320, me=0x105251cd0,
recv=140397325250640) at vm_insnhelper.c:524
#23 0x0000000104fd625c in vm_exec_core (th=0x105201b60, initial=0) at
insns.def:1006
#24 0x0000000104fe5e8e in vm_exec (th=0x105201b60) at vm.c:1147
#25 0x0000000104fe49a4 in invoke_block_from_c (th=0x105201b60,
block=0x1053fe558, self=140397327935920, argc=1, argv=0x7fff64a5ab38,
blockptr=0x0, cref=0x0) at vm.c:558
#26 0x0000000104fe4a2b in vm_yield (th=0x105201b60, argc=1,
argv=0x7fff64a5ab38) at vm.c:588
#27 0x0000000104fe1374 in rb_yield_0 (argc=1, argv=0x7fff64a5ab38) at
vm_eval.c:740
#28 0x0000000104fe1345 in rb_yield (val=140397329961240) at vm_eval.c:750
#29 0x0000000104e7d413 in rb_ary_collect (ary=140397329954040) at array.c:2166
#30 0x0000000104fdc604 in call_cfunc (func=0x104e7d348
<rb_ary_collect>, recv=140397329954040, len=0, argc=0,
argv=0x1053008e0) at vm_insnhelper.c:318
#31 0x0000000104fdc455 in vm_call_cfunc (th=0x105201b60,
reg_cfp=0x1053fe530, num=0, recv=140397329954040,
blockptr=0x1053fe558, me=0x10523e8b0) at vm_insnhelper.c:402
#32 0x0000000104fdb63c in vm_call_method (th=0x105201b60,
cfp=0x1053fe530, num=0, blockptr=0x1053fe558, flag=0, id=1536,
me=0x10523e8b0, recv=140397329954040) at vm_insnhelper.c:524
#33 0x0000000104fd625c in vm_exec_core (th=0x105201b60, initial=0) at
insns.def:1006
#34 0x0000000104fe5e8e in vm_exec (th=0x105201b60) at vm.c:1147
#35 0x0000000104fe49a4 in invoke_block_from_c (th=0x105201b60,
block=0x1053fe710, self=140397327935920, argc=2, argv=0x7fff64a5bc40,
blockptr=0x0, cref=0x0) at vm.c:558
#36 0x0000000104fe4a2b in vm_yield (th=0x105201b60, argc=2,
argv=0x7fff64a5bc40) at vm.c:588
#37 0x0000000104fe1374 in rb_yield_0 (argc=2, argv=0x7fff64a5bc40) at
vm_eval.c:740
#38 0x0000000104fe157e in rb_yield_values (n=2) at vm_eval.c:772
#39 0x0000000104ea0100 in each_with_index_i (i=140397330196880,
memo=140734881973352, argc=1, argv=0x7fff64a5bf78) at enum.c:1582
#40 0x0000000104fd25c1 in vm_yield_with_cfunc (th=0x105201b60,
block=0x1053fe6b8, self=140397330192720, argc=1, argv=0x7fff64a5bf78,
blockargptr=0x0) at vm_insnhelper.c:728
#41 0x0000000104fe49d5 in invoke_block_from_c (th=0x105201b60,
block=0x1053fe6b8, self=140397330192720, argc=1, argv=0x7fff64a5bf78,
blockptr=0x0, cref=0x0) at vm.c:561
#42 0x0000000104fe4a2b in vm_yield (th=0x105201b60, argc=1,
argv=0x7fff64a5bf78) at vm.c:588
#43 0x0000000104fe1374 in rb_yield_0 (argc=1, argv=0x7fff64a5bf78) at
vm_eval.c:740
#44 0x0000000104fe1345 in rb_yield (val=140397330196880) at vm_eval.c:750
#45 0x0000000104e7a923 in rb_ary_each (ary=140397330192720) at array.c:1427
#46 0x0000000104fdc604 in call_cfunc (func=0x104e7a899 <rb_ary_each>,
recv=140397330192720, len=0, argc=0, argv=0x105300858) at
vm_insnhelper.c:318
#47 0x0000000104fdfa7b in vm_call0 (th=0x105201b60,
recv=140397330192720, id=424, argc=0, argv=0x105300858,
me=0x10523de20) at vm_eval.c:79
#48 0x0000000104fe0eb9 in rb_call0 (recv=140397330192720, mid=424,
argc=0, argv=0x105300858, scope=CALL_FCALL, self=6) at vm_eval.c:235
#49 0x0000000104fe0e0c in rb_call (recv=140397330192720, mid=424,
argc=0, argv=0x105300858, scope=CALL_FCALL) at vm_eval.c:438
#50 0x0000000104fe1a43 in iterate_method (obj=140734881973264) at vm_eval.c:928
#51 0x0000000104fe184e in rb_iterate (it_proc=0x104fe1a06
<iterate_method>, data1=140734881973264, bl_proc=0x104ea00a6
<each_with_index_i>, data2=140734881973352) at vm_eval.c:861
#52 0x0000000104fe1a9d in rb_block_call (obj=140397330192720, mid=424,
argc=0, argv=0x105300858, bl_proc=0x104ea00a6 <each_with_index_i>,
data2=140734881973352) at vm_eval.c:941
#53 0x0000000104ea0176 in enum_each_with_index (argc=0,
argv=0x105300858, obj=140397330192720) at enum.c:1612
#54 0x0000000104fdc5ec in call_cfunc (func=0x104ea0107
<enum_each_with_index>, recv=140397330192720, len=-1, argc=0,
argv=0x105300858) at vm_insnhelper.c:315
#55 0x0000000104fdc455 in vm_call_cfunc (th=0x105201b60,
reg_cfp=0x1053fe6e8, num=0, recv=140397330192720,
blockptr=0x1053fe710, me=0x10520f610) at vm_insnhelper.c:402
#56 0x0000000104fdb63c in vm_call_method (th=0x105201b60,
cfp=0x1053fe6e8, num=0, blockptr=0x1053fe710, flag=0, id=1696,
me=0x10520f610, recv=140397330192720) at vm_insnhelper.c:524
#57 0x0000000104fd625c in vm_exec_core (th=0x105201b60, initial=0) at
insns.def:1006
#58 0x0000000104fe5e8e in vm_exec (th=0x105201b60) at vm.c:1147
#59 0x0000000104fe49a4 in invoke_block_from_c (th=0x105201b60,
block=0x1053fe870, self=140397327935920, argc=1, argv=0x7fff64a5d528,
blockptr=0x0, cref=0x0) at vm.c:558
#60 0x0000000104fe4a2b in vm_yield (th=0x105201b60, argc=1,
argv=0x7fff64a5d528) at vm.c:588
#61 0x0000000104fe1374 in rb_yield_0 (argc=1, argv=0x7fff64a5d528) at
vm_eval.c:740
#62 0x0000000104fe1345 in rb_yield (val=140397324500880) at vm_eval.c:750
#63 0x0000000104e7a923 in rb_ary_each (ary=140397364518360) at array.c:1427
#64 0x0000000104fdc604 in call_cfunc (func=0x104e7a899 <rb_ary_each>,
recv=140397364518360, len=0, argc=0, argv=0x1053007d0) at
vm_insnhelper.c:318
#65 0x0000000104fdc455 in vm_call_cfunc (th=0x105201b60,
reg_cfp=0x1053fe848, num=0, recv=140397364518360,
blockptr=0x1053fe870, me=0x10523de20) at vm_insnhelper.c:402
#66 0x0000000104fdb63c in vm_call_method (th=0x105201b60,
cfp=0x1053fe848, num=0, blockptr=0x1053fe870, flag=0, id=424,
me=0x10523de20, recv=140397364518360) at vm_insnhelper.c:524
#67 0x0000000104fd625c in vm_exec_core (th=0x105201b60, initial=0) at
insns.def:1006
#68 0x0000000104fe5e8e in vm_exec (th=0x105201b60) at vm.c:1147
#69 0x0000000104fe49a4 in invoke_block_from_c (th=0x105201b60,
block=0x1053fe978, self=140397327935920, argc=1, argv=0x7fff64a5e628,
blockptr=0x0, cref=0x0) at vm.c:558
#70 0x0000000104fe4a2b in vm_yield (th=0x105201b60, argc=1,
argv=0x7fff64a5e628) at vm.c:588
#71 0x0000000104fe1374 in rb_yield_0 (argc=1, argv=0x7fff64a5e628) at
vm_eval.c:740
#72 0x0000000104fe1345 in rb_yield (val=140397323994000) at vm_eval.c:750
#73 0x0000000104e7a923 in rb_ary_each (ary=140397323993480) at array.c:1427


-- 
Geoffrey Ducharme

Skype: offercharm
Phone: [phone]
Email: [e-mail]