Bug #17653: SEGFAULT in ossl_ssl_read_internal

• Status: Closed
• Assignee: rhenium (Kazuki Yamaguchi)
• Target version: -
• ruby -v: ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-linux]
• Backport: 2.5: DONTNEED, 2.6: DONTNEED, 2.7: DONTNEED, 3.0: DONE

[vo.x (Vit Ondruch)]

Trying to run excon test suite agains Ruby 3.0, it mysteriously fails from time to time. Digging deeper and executing the Rack server on background with debug option, I started to observer this error:

... snip ...

/usr/share/ruby/openssl/buffering.rb:80: [BUG] during_gc != 0
ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-linux]
-- Control frame information -----------------------------------------------
c:0014 p:---- s:0103 e:000102 CFUNC  :sysread
c:0013 p:0015 s:0098 e:000096 METHOD /usr/share/ruby/openssl/buffering.rb:80
c:0012 p:0057 s:0093 e:000092 METHOD /usr/share/ruby/openssl/buffering.rb:121
c:0011 p:0011 s:0086 e:000085 BLOCK  /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:565
c:0010 p:0051 s:0083 e:000082 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/utils.rb:258
c:0009 p:0023 s:0076 e:000075 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:564
c:0008 p:0009 s:0069 e:000068 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:579
c:0007 p:0127 s:0063 e:000062 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:518
c:0006 p:0034 s:0054 E:002228 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:257
c:0005 p:0033 s:0049 e:000047 METHOD /usr/share/gems/gems/rack-2.2.3/lib/rack/handler/webrick.rb:71
c:0004 p:0189 s:0032 e:000031 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:140
c:0003 p:0256 s:0021 e:000020 METHOD /usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:96
c:0002 p:0136 s:0009 e:000008 BLOCK  /usr/share/gems/gems/webrick-1.7.0/lib/webrick/server.rb:310 [FINISH]
c:0001 p:---- s:0003 e:000002 (none) [FINISH]
-- Ruby level backtrace information ----------------------------------------
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/server.rb:310:in `block in start_thread'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:96:in `run'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:140:in `service'
/usr/share/gems/gems/rack-2.2.3/lib/rack/handler/webrick.rb:71:in `service'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:257:in `body'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:518:in `read_body'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:579:in `read_data'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:564:in `_read_data'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/utils.rb:258:in `timeout'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httprequest.rb:565:in `block in _read_data'
/usr/share/ruby/openssl/buffering.rb:121:in `read'
/usr/share/ruby/openssl/buffering.rb:80:in `fill_rbuff'
/usr/share/ruby/openssl/buffering.rb:80:in `sysread'
-- C level backtrace information -------------------------------------------
/lib64/libruby.so.3.0(0x7f96979f6e0a) [0x7f96979f6e0a]
/lib64/libruby.so.3.0(0x7f969784bbf6) [0x7f969784bbf6]
/lib64/libruby.so.3.0(rb_bug+0xa1) [0x7f96977d775b]
/lib64/libruby.so.3.0(0x7f96977d7fc4) [0x7f96977d7fc4]
/lib64/libruby.so.3.0(0x7f969786f05e) [0x7f969786f05e]
/lib64/libruby.so.3.0(0x7f969786f113) [0x7f969786f113]
/lib64/libruby.so.3.0(0x7f96979314ff) [0x7f96979314ff]
/lib64/libruby.so.3.0(0x7f9697870885) [0x7f9697870885]
/lib64/libruby.so.3.0(0x7f969786ec0b) [0x7f969786ec0b]
/lib64/libruby.so.3.0(0x7f969786f05e) [0x7f969786f05e]
/lib64/libruby.so.3.0(0x7f969786f223) [0x7f969786f223]
/lib64/libruby.so.3.0(0x7f969797fd2d) [0x7f969797fd2d]
/usr/lib64/ruby/openssl.so(0x7f9693d80589) [0x7f9693d80589]
/lib64/libruby.so.3.0(0x7f96979db1d5) [0x7f96979db1d5]
/lib64/libruby.so.3.0(0x7f96979dd536) [0x7f96979dd536]
/lib64/libruby.so.3.0(0x7f96979e01d2) [0x7f96979e01d2]
/lib64/libruby.so.3.0(rb_vm_exec+0x115) [0x7f96979e5555]
/lib64/libruby.so.3.0(rb_vm_invoke_proc+0x5f) [0x7f96979ea30f]
/lib64/libruby.so.3.0(0x7f96979a7ca9) [0x7f96979a7ca9]
/lib64/libruby.so.3.0(0x7f96979a82e3) [0x7f96979a82e3]
/lib64/libruby.so.3.0(0x7f96979a8a9d) [0x7f96979a8a9d]
/lib64/libpthread.so.0(start_thread+0xe9) [0x7f969759f1c9]
/lib64/libc.so.6(clone+0x43) [0x7f96976d1473]
-- Other runtime information -----------------------------------------------

... snip ...

So executing the rackup server outside of the test suite:

$ "rackup" "-s" "webrick" "--host" 127.0.0.1 /builddir/build/BUILD/excon-0.74.0/usr/share/gems/gems/excon-0.74.0/tests/rackups/ssl.ru

with attached GDB, I was finally able to obtain this backtrace:

(gdb) 
#0  0x00007f8bedde5292 in raise () from target:/lib64/libc.so.6
#1  0x00007f8beddce8a4 in abort () from target:/lib64/libc.so.6
#2  0x00007f8bedfae760 in die () at error.c:750
#3  rb_bug (fmt=fmt@entry=0x7f8bee1e1b29 "during_gc != 0") at error.c:773
#4  0x00007f8bedfaefc4 in gc_enter (lock_lev=<optimized out>, event=<optimized out>, objspace=<optimized out>) at gc.c:8463
#5  gc_rest (objspace=<optimized out>) at gc.c:8325
#6  0x00007f8bee04605e in gc_rest (objspace=0x5628b1dc77f0) at gc.c:8323
#7  objspace_malloc_increase (objspace=0x5628b1dc77f0, new_size=<optimized out>, old_size=<optimized out>, type=<optimized out>, mem=<optimized out>) at gc.c:10445
#8  0x00007f8bee046113 in objspace_malloc_fixup (size=<optimized out>, mem=0x7f8be411f620, objspace=0x5628b1dc77f0) at gc.c:10527
#9  objspace_xcalloc (size=<optimized out>, objspace=0x5628b1dc77f0) at gc.c:10850
#10 ruby_xcalloc_body (n=<optimized out>, size=<optimized out>) at gc.c:10856
#11 0x00007f8bee1084ff in default_rand () at random.c:171
#12 default_rand () at random.c:166
#13 random_mt_free (ptr=0x5628b2b567f0) at random.c:260
#14 0x00007f8bee047885 in obj_free (obj=94732796930160, objspace=0x5628b1dc77f0) at gc.c:2946
#15 gc_page_sweep (sweep_page=0x5628b2afe1c0, heap=0x5628b1dc7818, objspace=0x5628b1dc77f0) at gc.c:4907
#16 gc_sweep_step (objspace=0x5628b1dc77f0, heap=0x5628b1dc7818) at gc.c:5127
#17 0x00007f8bee045c0b in gc_sweep_rest (objspace=<optimized out>) at gc.c:5183
#18 gc_rest (objspace=0x5628b1dc77f0) at gc.c:8333
#19 0x00007f8bee04605e in gc_rest (objspace=0x5628b1dc77f0) at gc.c:8323
#20 objspace_malloc_increase (objspace=0x5628b1dc77f0, new_size=<optimized out>, old_size=<optimized out>, type=<optimized out>, mem=<optimized out>) at gc.c:10445
#21 0x00007f8bee046223 in objspace_malloc_fixup (size=<optimized out>, mem=0x7f8be4e0dbb0, objspace=0x5628b1dc77f0) at gc.c:10527
#22 objspace_xmalloc0 (objspace=0x5628b1dc77f0, size=size@entry=16385) at gc.c:10598
#23 0x00007f8bee04a5f9 in ruby_xmalloc2_body (size=1, n=16385) at gc.c:10840
#24 0x00007f8bee156d2d in str_new0 (klass=94732783446160, ptr=ptr@entry=0x0, len=len@entry=16384, termlen=termlen@entry=1) at string.c:798
#25 0x00007f8bee1588ae in str_new (len=16384, ptr=0x0, klass=<optimized out>) at string.c:815
#26 0x00007f8bea4fb589 in ossl_ssl_read_internal (argc=<optimized out>, argv=<optimized out>, self=94732787301960, nonblock=0) at ossl_ssl.c:1834
#27 0x00007f8bee1b21d5 in vm_call_cfunc_with_frame (ec=0x5628b298a860, reg_cfp=0x7f8be9f2a918, calling=<optimized out>) at /usr/src/debug/ruby-3.0.0-145.fc34.x86_64/vm_insnhelper.c:2898
#28 0x00007f8bee1b4536 in vm_sendish (ec=0x5628b298a860, reg_cfp=0x7f8be9f2a918, cd=0x5628b21511b0, block_handler=<optimized out>, method_explorer=<optimized out>)
    at /usr/src/debug/ruby-3.0.0-145.fc34.x86_64/vm_callinfo.h:336
#29 0x00007f8bee1b71d2 in vm_exec_core (ec=0x5628b298a860, initial=140238901125456) at /usr/src/debug/ruby-3.0.0-145.fc34.x86_64/insns.def:789
#30 0x00007f8bee1bc555 in rb_vm_exec (ec=0x5628b298a860, mjit_enable_p=<optimized out>) at vm.c:2172
#31 0x00007f8bee1c130f in rb_vm_invoke_proc (ec=<optimized out>, proc=proc@entry=0x5628b26b24d0, argc=argc@entry=0, argv=argv@entry=0x7f8be9e2ab40, kw_splat=<optimized out>, 
    passed_block_handler=passed_block_handler@entry=0) at vm.c:1485
#32 0x00007f8bee17eca9 in thread_do_start_proc (th=0x5628b2988090) at thread.c:745
#33 0x00007f8bee17f2e3 in thread_do_start (th=0x5628b2988090) at thread.c:766
#34 thread_start_func_2 (th=0x5628b2988090, stack_start=<optimized out>) at thread.c:822
#35 0x00007f8bee17fa9d in thread_start_func_1 (th_ptr=<optimized out>) at /usr/src/debug/ruby-3.0.0-145.fc34.x86_64/thread_pthread.c:994
#36 0x00007f8bedd761c9 in start_thread () from target:/lib64/libpthread.so.0
#37 0x00007f8bedea8473 in clone () from target:/lib64/libc.so.6
(gdb) 

This resembles the #17102 as well as possibly #12292.

[vo.x (Vit Ondruch)]

I should also mention, that the failure typically happens here:

tests('response.body').returns("5000000") do
  response = connection.request(:method => :post, :path => '/body-sink', :headers => { 'Content-Type' => 'text/plain' }, :body => 'x' * 5_000_000)
  response.body
end

If I am not mistaken, this test send 5MB post request to the server, that is what probably triggers allocation of additional memory and therefore GC run.

[vo.x (Vit Ondruch)]

• Assignee set to rhenium (Kazuki Yamaguchi)

[rhenium (Kazuki Yamaguchi)]

• Status changed from Open to Closed
• Backport changed from 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN to 2.5: DONTNEED, 2.6: DONTNEED, 2.7: DONTNEED, 3.0: REQUIRED

vo.x (Vit Ondruch) wrote:

(gdb) 
#0  0x00007f8bedde5292 in raise () from target:/lib64/libc.so.6
#1  0x00007f8beddce8a4 in abort () from target:/lib64/libc.so.6
#2  0x00007f8bedfae760 in die () at error.c:750
#3  rb_bug (fmt=fmt@entry=0x7f8bee1e1b29 "during_gc != 0") at error.c:773
#4  0x00007f8bedfaefc4 in gc_enter (lock_lev=<optimized out>, event=<optimized out>, objspace=<optimized out>) at gc.c:8463
#5  gc_rest (objspace=<optimized out>) at gc.c:8325
#6  0x00007f8bee04605e in gc_rest (objspace=0x5628b1dc77f0) at gc.c:8323
#7  objspace_malloc_increase (objspace=0x5628b1dc77f0, new_size=<optimized out>, old_size=<optimized out>, type=<optimized out>, mem=<optimized out>) at gc.c:10445
#8  0x00007f8bee046113 in objspace_malloc_fixup (size=<optimized out>, mem=0x7f8be411f620, objspace=0x5628b1dc77f0) at gc.c:10527
#9  objspace_xcalloc (size=<optimized out>, objspace=0x5628b1dc77f0) at gc.c:10850
#10 ruby_xcalloc_body (n=<optimized out>, size=<optimized out>) at gc.c:10856
#11 0x00007f8bee1084ff in default_rand () at random.c:171
#12 default_rand () at random.c:166
#13 random_mt_free (ptr=0x5628b2b567f0) at random.c:260
#14 0x00007f8bee047885 in obj_free (obj=94732796930160, objspace=0x5628b1dc77f0) at gc.c:2946
#15 gc_page_sweep (sweep_page=0x5628b2afe1c0, heap=0x5628b1dc7818, objspace=0x5628b1dc77f0) at gc.c:4907

This sounds like the bug in Random fixed in master a while ago: https://github.com/ruby/ruby/commit/265c0022390e3dcd4ff692fc77d29b94e652c877

I'm attaching the commit for backporting to 3.0 since there doesn't seem to be an issue associated with it yet.

[vo.x (Vit Ondruch)]

Thx for pouting out the patch. With the patch applied, I have run the excon test suite a hundred times without failure, so it seem that is the right one.

[naruse (Yui NARUSE)]

• Backport changed from 2.5: DONTNEED, 2.6: DONTNEED, 2.7: DONTNEED, 3.0: REQUIRED to 2.5: DONTNEED, 2.6: DONTNEED, 2.7: DONTNEED, 3.0: DONE

ruby_3_0 713d6d5eb05de06a0de25feef801ff8c72c65754 merged revision(s) 265c0022390e3dcd4ff692fc77d29b94e652c877.