Bug #6168

Segfault in OpenSSL bindings

Added by Nguma Abojo about 2 years ago. Updated about 1 year ago.

[ruby-core:43373]
Status:Assigned
Priority:Normal
Assignee:Martin Bosslet
Category:ext
Target version:next minor
ruby -v:ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-linux] Backport:

Description

Hello,

A few days ago I updated my Arch Linux server to OpenSSL 1.0.1-1 and Ruby 1.9.3_p125-2. Since then I have been experiencing an odd service failure where a Ruby TLS service of mine would disconnect users with "invalid MAC" exceptions. Shortly after or even before that exception occurs, it segfaults in openssl/buffering.rb. I am not entirely sure whether this is a Ruby OpenSSL bindings bug or even an OpenSSL bug or simply a user error. This is what it prints:

/usr/lib/ruby/1.9.1/openssl/buffering.rb:318: [BUG] Segmentation fault
ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0016 p:---- s:0081 b:0081 l:000080 d:000080 CFUNC :syswrite
c:0015 p:0181 s:0077 b:0077 l:000076 d:000076 METHOD /usr/lib/ruby/1.9.1/openssl/buffering.rb:318
c:0014 p:0030 s:0068 b:0068 l:000067 d:000067 METHOD /usr/lib/ruby/1.9.1/openssl/buffering.rb:415
c:0013 p:0046 s:0063 b:0063 l:000062 d:000062 METHOD /usr/lib/ruby/1.9.1/nil/communication.rb:87
c:0012 p:0011 s:0057 b:0057 l:000051 d:000056 BLOCK /home/void/code/warehouse/notification/NotificationClient.rb:29
c:0011 p:0019 s:0055 b:0055 l:000054 d:000054 METHOD internal:prelude:10
c:0010 p:0013 s:0052 b:0052 l:000051 d:000051 METHOD /home/void/code/warehouse/notification/NotificationClient.rb:29
c:0009 p:0088 s:0048 b:0048 l:000047 d:000047 METHOD /home/void/code/warehouse/notification/NotificationServer.rb:200
c:0008 p:---- s:0039 b:0039 l:000038 d:000038 FINISH
c:0007 p:---- s:0037 b:0037 l:000036 d:000036 CFUNC :call
c:0006 p:0218 s:0032 b:0032 l:000031 d:000031 METHOD /home/void/code/warehouse/notification /NotificationServer.rb:185
c:0005 p:0146 s:0023 b:0023 l:000022 d:000022 METHOD /home/void/code/warehouse/notification /NotificationServer.rb:162
c:0004 p:0171 s:0014 b:0014 l:000013 d:000013 METHOD /home/void/code/warehouse/notification /NotificationServer.rb:139
c:0003 p:0012 s:0006 b:0006 l:000118 d:000005 BLOCK /home/void/code/warehouse/notification /NotificationServer.rb:102
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:---- s:0002 b:0002 l:000001 d:000001 TOP

-- Ruby level backtrace information ----------------------------------------
/home/void/code/warehouse/notification/NotificationServer.rb:102:in block in runServer'
/home/void/code/warehouse/notification/NotificationServer.rb:139:in
handleClient'
/home/void/code/warehouse/notification/NotificationServer.rb:162:in processClientCommunication'
/home/void/code/warehouse/notification/NotificationServer.rb:185:in
processClientInput'
/home/void/code/warehouse/notification/NotificationServer.rb:185:in call'
/home/void/code/warehouse/notification/NotificationServer.rb:200:in
rpcHandler'
/home/void/code/warehouse/notification/NotificationClient.rb:29:in sendData'
<internal:prelude>:10:in
synchronize'
/home/void/code/warehouse/notification/NotificationClient.rb:29:in block in sendData'
/usr/lib/ruby/1.9.1/nil/communication.rb:87:in
sendData'
/usr/lib/ruby/1.9.1/openssl/buffering.rb:415:in print'
/usr/lib/ruby/1.9.1/openssl/buffering.rb:318:in
do_write'
/usr/lib/ruby/1.9.1/openssl/buffering.rb:318:in `syswrite'

-- C level backtrace information -------------------------------------------
/usr/lib/libruby.so.1.9(+0x158ee9) [0x7f3aa715fee9]
/usr/lib/libruby.so.1.9(+0x59f99) [0x7f3aa7060f99]
/usr/lib/libruby.so.1.9(rb_bug+0xb7) [0x7f3aa70619c7]
/usr/lib/libruby.so.1.9(+0xf945f) [0x7f3aa710045f]
/lib/libc.so.6(+0x349f0) [0x7f3aa6c9a9f0]
/usr/lib/libcrypto.so.1.0.0(RC4+0x431) [0x7f3aa4db6c31]

error.log (94.3 KB) Larry Kyrala, 03/28/2012 04:38 AM

ruby-lang-6168.zip (4.75 KB) Larry Kyrala, 03/29/2012 06:49 AM


Related issues

Related to ruby-trunk - Bug #6227: [mingw] openssl backport causing test error Assigned 03/31/2012

History

#1 Updated by Martin Bosslet about 2 years ago

  • Category set to ext
  • Status changed from Open to Assigned
  • Assignee set to Martin Bosslet

#2 Updated by Larry Kyrala about 2 years ago

This also happens in 1.9.2-p318:

While using the mail gem (http://rubygems.org/gems/mail) in a ruby-debug19 context:

85 emails = Mail.find(:mailbox => opts[:mailbox], :keys => ["ALL", "UNSEEN"], :count => 9999) do |email, imap, messageid|
86 debugger
87 print '.'
88 end
(rdb:1) imap.uid
store(messageid, "+FLAGS", [:Seen])
/local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/openssl/buffering.rb:36: [BUG] Segmentation fault
ruby 1.9.2p318 (2012-02-14 revision 34678) [x86
64-linux]

see attached error.log for details.

environment details:

$ uname -a
Linux ah-lkyrala2u 3.0.0-16-generic #29-Ubuntu SMP Tue Feb 14 12:48:51 UTC 2012 x8664 x8664 x86_64 GNU/Linux

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 11.10
Release: 11.10
Codename: oneiric

$ dpkg -l | grep SSL
ii libcurl3 7.21.6-3ubuntu3.2 Multi-protocol file transfer library (OpenSSL)
rc libcurl3:i386 7.21.6-3ubuntu3.2 Multi-protocol file transfer library (OpenSSL)
ii libcurl4-openssl-dev 7.21.6-3ubuntu3.2 Development files and documentation for libcurl (OpenSSL)
ii libssl-dev 1.0.0e-2ubuntu4.2 SSL development libraries, header files and documentation
ii libssl-doc 1.0.0e-2ubuntu4.2 SSL development documentation documentation
ii libssl1.0.0 1.0.0e-2ubuntu4.2 SSL shared libraries
rc libssl1.0.0:i386 1.0.0e-2ubuntu4.2 SSL shared libraries
ii openssl 1.0.0e-2ubuntu4.2 Secure Socket Layer (SSL) binary and related cryptographic tools
ii python-openssl 0.12-1ubuntu1 Python wrapper around the OpenSSL library
ii ssl-cert 1.0.28 simple debconf wrapper for OpenSSL

#3 Updated by Larry Kyrala about 2 years ago

trying again pointing at openssl dir to see if that makes a difference:

$ rvm reinstall 1.9.2 --with-openssl-dir=/usr/include/openssl

nope, same seg fault.

#4 Updated by Eric Hodel about 2 years ago

The error.log point to rbcheckfuncall, not OpenSSL, so this may not be Martin's bug

#5 Updated by Martin Bosslet about 2 years ago

Hmm, the error logs don't really give away what happens. But it shouldn't segfault, that's for sure. What I would really appreciate is some code snippet that reliably reproduces the phenomenon on your side, Larry. Could you please try to isolate the behavior? Then at least I have a chance going through execution paths trying to reason why it might segfault on your side...

#6 Updated by Eric Hodel about 2 years ago

The second log uses ruby-debug and could be the cause of the second report. If this could be confirmed as another crash in sys write without use of ruby-debug that would be helpful.

#7 Updated by Larry Kyrala about 2 years ago

Ok, I think I have a test case for you Martin... I was able to reproduce this again Google's IMAP server, so I created a dummy test account and a simple test case. Note: it only segfaults when in debug, I have no idea why? (is the debugger trying to tack something on to allocated buffers being passed to openssl?)

Anyway, download the zip, unzip it and look at the contained error.log for a record of what I ran and how I reproduced the problem.

Let me know if you have questions.

#8 Updated by Larry Kyrala about 2 years ago

Ok, running that without the debugger gives a better error:

/local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:1099:in get_tagged_response': STORE attempt on READ-ONLY folder (Failure) (Net::IMAP::NoResponseError)
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:1153:in
block in sendcommand'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/monitor.rb:201:in mon_synchronize'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:1135:in
send
command'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:1317:in block in store_internal'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/monitor.rb:201:in
monsynchronize'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:1315:in store_internal'
from /local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/net/imap.rb:780:in
uid
store'
from test.rb:19:in block in <main>'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/network/retriever_methods/imap.rb:80:in
block (2 levels) in find'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/network/retrievermethods/imap.rb:75:in each'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/network/retriever_methods/imap.rb:75:in
block in find'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/network/retriever
methods/imap.rb:152:in start'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/network/retriever_methods/imap.rb:65:in
find'
from /local/rvm/gems/ruby-1.9.2-p318@test6168/gems/mail-2.4.4/lib/mail/mail.rb:147:in find'
from test.rb:17:in
'

So this is really weird... I changed the code to:
emails = Mail.find(:readonly => true) do |email, imap, messageid|

and it totally works without the error. It's like line 74 on https://github.com/mikel/mail/blob/master/lib/mail/network/retriever_methods/imap.rb somehow implemented IMAP SELECT and EXAMINE backwards. (EXAMINE is supposed to be read-only, while SELECT is rw... but if :read_only isn't defined, it defaults to false and that should use SELECT as far as I can tell.

I can only assume that the debugger is somehow interfering with the raise of NoResponseError, but I'm not sure why the seg fault happens to appear in openssl.

Weird.

#9 Updated by Martin Bosslet about 2 years ago

  • Priority changed from High to Normal

Weird indeed, but thanks for your in-depth analysis and to Eric
for the hint with the debugger. I'll have a look at your example,
maybe I can find out why the seg fault happens in OpenSSL. But
good news that you at least know how to circumvent it for now :)
I'll put it on normal priority then, since it seems not to occur
under "normal" circumstances.

#10 Updated by Larry Kyrala about 2 years ago

Cool. Both of our segfault locations in ruby code suggest some kind of buffer sizing problem (mine segs on read, yours on write).

Looking at the two locations where the segfault occurs:

/local/rvm/rubies/ruby-1.9.2-p318/lib/ruby/1.9.1/openssl/buffering.rb
line 38:
def fillrbuff
begin
=> @rbuffer << self.sysread(BLOCK
SIZE)
rescue Errno::EAGAIN
retry
rescue EOFError
=* @eof = true
end
end

line 318:
def print(args)
s = ""
args.each{ |arg| s << arg.to_s }
=
do_write(s)
nil
end

In my experience, there are many things that can potentially screw with buffers passed back and forth between ruby and native C.

Some things that come to mind: who owns the buffers (ruby or C?) here. Are they padded? (on different architectures?) If there is a choice between calculating the buffer size (via ruby) and getting the return buffer size from libssl, it's better to ask libssl (as crypto buffers vary by implementation and encoding and will most likely differ from ruby's assumptions). Another strategy may be to copy the unencoded buffer from openssl native to ruby before passing it back to be used in ruby string operations or vice versa. There were a lot of changes in 1.9 dealing with byte size and encodings that may have invalidated some edge-case assumptions in the openssl binding that are rather ahem hard to test and reproduce.

#11 Updated by Yui NARUSE about 1 year ago

  • Target version changed from 1.9.3 to next minor

Also available in: Atom PDF