Bug #6168: Segfault in OpenSSL bindings

• Status: Third Party's Issue
• Assignee: -
• Target version: -
• ruby -v: ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-linux]

[amasal (Nguma Abojo)]

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]

[MartinBosslet (Martin Bosslet)]

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

[coldnebo (Larry Kyrala)]

• File error.log error.log added

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, message_id|
86 debugger
87 print '.'
88 end
(rdb:1) imap.uid_store(message_id, "+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 x86_64 x86_64 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

[coldnebo (Larry Kyrala)]

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.

[drbrain (Eric Hodel)]

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

[MartinBosslet (Martin Bosslet)]

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...

[drbrain (Eric Hodel)]

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.

[coldnebo (Larry Kyrala)]

• File ruby-lang-6168.zip ruby-lang-6168.zip added

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.

[coldnebo (Larry Kyrala)]

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 send_command'
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 mon_synchronize'
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/retriever_methods/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(:read_only => true) do |email, imap, message_id|

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.

[MartinBosslet (Martin Bosslet)]

• Priority changed from 5 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.

[coldnebo (Larry Kyrala)]

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 fill_rbuff
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.

[naruse (Yui NARUSE)]

• Target version changed from 1.9.3 to 2.6

[zzak (zzak _)]

• Assignee changed from MartinBosslet (Martin Bosslet) to 7150

[naruse (Yui NARUSE)]

• Related to Bug #12309: Segmentation fault caused by OpenSSL added

[naruse (Yui NARUSE)]

• Related to Bug #12126: [PATCH] openssl: accept moving write buffer for write_nonblock added

[rhenium (Kazuki Yamaguchi)]

• Status changed from Assigned to Third Party's Issue

I reproduce the segmentation fault with Larry's reproducer. It seems like a ruby-debug bug.

a.rb:

require "ruby-debug"

debugger
sleep

and run it

bash$ ~/ruby192/bin/ruby a.rb
a.rb:4
sleep
(rdb:1) eval Thread.new{Thread.stop} && Thread.stop
a.rb:4: [BUG] Segmentation fault (core dumped)

[rhenium (Kazuki Yamaguchi)]

• Related to deleted (Bug #6227: [mingw] openssl backport causing test error)

[rhenium (Kazuki Yamaguchi)]

• Related to deleted (Bug #12309: Segmentation fault caused by OpenSSL)

[rhenium (Kazuki Yamaguchi)]

• Related to deleted (Bug #12126: [PATCH] openssl: accept moving write buffer for write_nonblock)