History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: JRUBY-1692
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Ola Bini
Reporter: Bill Dortch
Votes: 0
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
JRuby

jopenssl Cipher fails after first message (Net::SSH)

Created: 09/Dec/07 07:24 AM   Updated: 14/Aug/08 04:51 AM
Component/s: OpenSSL
Affects Version/s: None
Fix Version/s: None

Time Tracking:
Not Specified

File Attachments: 1. File sst.rb (3 kb)

Environment: jopenssl trunk, JRuby trunk, WinXP, Java 1.6, bcprov-jdk15-137.jar, Net::SSH 1.1.2; server sshd is OpenSSH 4.7 (cygwin)

Testcase included: yes


 Description  « Hide
jopenssl support for Net::SSH is nearly working (the new BN and DH classes used for key exchange appear to work), but I'm getting a failure that appears to be caused by a bug in cipher code (org.jruby.ext.openssl.Cipher.java).

Here's what happens, in brief (I've attached the debug output below, and have attached some code to repro):

  • the client and server negotiate algorithms and exchange keys
  • Net::SSH creates two ciphers, one for encrypt, one for decrypt
  • Net::SSH uses encrypt cipher to encrypt and send message "ssh-userauth" (plus some header fields)
  • Net::SSH uses decrypt cipher to decrypt the response, which also has the value "ssh-userauth" (plus headers)

So far, so good – we've encrypted and sent a message, and received and decrypted a valid response. Now:

  • Net::SSH uses encrypt cipher to encrypt and send a "ssh-connection" message, with username, password, and other info. We don't know if this worked, because:
  • Net::SSH uses decrypt cipher to decrypt response. This actually takes place in a couple of steps; first, a block is read and decrypted (packet header), and the message length is extracted. This length is then used to determine how much more data to read. However, the length returned is garbage. Typically very large or very small garbage: the RubyIO module attempts to allocate a ByteList, and either fails with a NegativeIndex exception, or dies with an OutOfMemory error (because the size was so large).

So it appears that the cipher doesn't work for more than one message. I've gone through the code and can't spot the bug; Cipher#final is being called between messages, and I've walked through the code (jopenssl and BC) and confirmed that BufferBlockCipher#doFinal is called, which appears to call #reset on the underlying Cipher; in the DES code at least, it appears that this correctly copies the original IV back to the buffer.

SO... I'm not sure why this is failing. On the other hand, there seems to be a fair amount of uncertainty in the Cipher implementation (I fixed a couple of glaring issues), so I wouldn't be surprised if there were some sort of misunderstanding of the BC interfaces (not so well documented) or the MRI-OpenSSL interface we're emulating (not documented at all), or the process in general. I'm certainly out of my depth here, though I've been doing a lot of research (Applied Cryptography is sorely out-of-date; the newer Practical Cryptography lacks details; Wikipedia has some pretty good info and pointers, like this one on modes: http://csrc.nist.gov/publications/nistpubs/800-38a/sp800-38a.pdf).

I've included a listing of a debug session below. The attached script will reproduce this, though you'll have to plug in your username and password first (and possibly hostname if you don't have sshd on your local machine – I've got OpenSSH running under cygwin on my WinXP box).

Try running the script under MRI-IRB to see what the results should look like. Getting pretty darned close, considering where things stood a few weeks ago.

c:\temp>jirb
irb(main):001:0> load 'sst.rb'
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: connecting
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.version_negotiator: remote server is "SSH-2.0-Op
enSSH_4.7"
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: waiting for packet from server...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: packet length(780) remai
ning(776)
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: received: "\024\224\315\
345Y\335f\276\223H$? \247\355M\315\000\000\000~diffie-hellman-group-exchange-sha256,diffie-hellman-g
roup-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1\000\000\000\017ssh-rsa,ssh
-dss\000\000\000\235aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes19
2-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr\000\000\000\235aes128-
cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-c
bc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr\000\000\000ihmac-md5,hmac-sha1,umac-64@openssh.co
m,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96\000\000\000ihmac-md5,hmac-sha1,
umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96\000\000\000\0
25none,zlib@openssh.com\000\000\000\025none,zlib@openssh.com\000\000\000\000\000\000\000\000\000\000
\000\000\000"
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: got packet of type 20
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: sending message >>"\024\336Sf\037\340\3
14\263hZ\310\005oQ\263X\\\000\000\000=diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1\
000\000\000\017ssh-rsa,ssh-dss\000\000\000D3des-cbc,aes128-cbc,blowfish-cbc,aes256-cbc,aes192-cbc,id
ea-cbc,none\000\000\000D3des-cbc,aes128-cbc,blowfish-cbc,aes256-cbc,aes192-cbc,idea-cbc,none\000\000
\0000hmac-md5,hmac-sha1,hmac-md5-96,hmac-sha1-96,none\000\000\0000hmac-md5,hmac-sha1,hmac-md5-96,hma
c-sha1-96,none\000\000\000\tnone,zlib\000\000\000\tnone,zlib\000\000\000\000\000\000\000\000\000\000
\000\000\000"<<
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: kex algorithm: diffie-hell
man-group-exchange-sha1
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: host key algorithm: ssh-rs
a
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: encryption algorithm (clie
nt-to-server): 3des-cbc
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: encryption algorithm (serv
er-to-client): 3des-cbc
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: hmac algorithm (client-to-
server): hmac-md5
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: hmac algorithm (server-to-
client): hmac-md5
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: compression algorithm (cli
ent-to-server): none
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: compression algorithm (ser
ver-to-client): none
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: language (client-to-server
):
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.algorithm_negotiator: language (server-to-client
):
OpenSSL::Cipher::Cipher:30: initialize arg: (12)[des-ede3-cbc]
OpenSSL::Cipher::Cipher:30: key_len: [24]
OpenSSL::Cipher::Cipher:30: block_size: [8]
OpenSSL::Cipher::Cipher:32: initialize arg: (12)[des-ede3-cbc]
OpenSSL::Cipher::Cipher:32: key_len: [24]
OpenSSL::Cipher::Cipher:32: block_size: [8]
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: sending message >>"\"\000\000\004\000\0
00\000\004\000\000\000 \000"<<
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: waiting for packet from server...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: packet length(148) remai
ning(144)
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: received: "\037\000\000\
000\201\000\312\255\335\354\026g\374h\265\372\025\325<N\0252\335$V\032\032-G\241,\001\253\352\036\00
0s\037i!\252\304\aB1\037\337\236cK\267\023\e\356\032\362@&\025T8\232\221\004%\340D\350\214\203Y\260\
020\365\255+\200\342\234\261\245\260'\261\235\236\001\246\366:oE\345\327\355/\366\242\240\010PP\247\
320\3170|=\265\035$\2205Y\a\264B|#\251\215\361\353\212\276\362\272 \233\267\261\265\247\257\000\000\
000\001\005"
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: got packet of type 31
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: sending message >>" \000\000\000\200L\0
27f\213\177\270\335\273\274\306\354\212\f\357\202;\216\361[I\003\242T$\252\311\360N\257W\334\261\374
\236\204N\177fY6\276%'D\367\023\344F9\305\323w\256\342|\341\236^\322\353\022o\344'3\374\206z1q)#\215
\205\234V\233\242 \306\n\t\\\v9\310]\035\316\236\364\357\330BL\"\225\021\037\370H`\236Z\334`L\257\33
0>\002L/\331'\020!\226\330e\316\236W+6\256\001j"<<
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: waiting for packet from server...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: packet length(700) remai
ning(696)
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: received: "!\000\000\001
\025\000\000\000\assh-rsa\000\000\000\001#\000\000\001\001\000\267}[l\241\"\205\315\241Z\n\245\342\2
56ydv\362\367v\252\257\273+X\237\026\362\365\027\314\263\353\262u\376W'o\003\355\a\323\252e\023\236\
362\273\312'\235\030\eF\212[\226\231\220'\217\\\344\263\273v#q\210\360\271>MW\300~\276\244oh\307jNJ\
370\252\223}5&\v\241X;\244m\363]\226\351\245m\t\232\340\276 \306\026[\310\363\3373c\216\t[\253\360\3
77t;H=\223\325\246\377\240\376\200\260#\240Ao/4\023i#E4\036\345{[]\016\000\370T\245s\256\364\310U\26
5L\204p\373\337\353\235\347\313`\n\251\"rn\325\376\361\376y\226~.\027\257\023W\272\005\232:\230Y8o\2
14\376\021\260\326\376\334\360o\315\235\200k\340*\227m0WoasA\016\307\a\204\\\347kD\221\344\327\250 \
336\310f\306\361>\031\232\311\310\373\223a\216\031\201>\313\354:%\021\274\217\000\000\000\200v\376AO
\004\a\024=Z 9\324&\032\217\337\030f_\211\314?\233T\300|\232\037\332\363\360'P\026\351\3428m\226A\26
3\t\355\341\200k\0239\2507\361\r\345\213\263\2567\262;\221@\027x\334`\332+l-\307\225\231\f\232\031\0
04\347\203\017?\322\362\vSI\301d\266\266\025''0\010T\370K\304lv\365\354I\3026'_l\3673\211\344\325TQ\
246\r\262\233\311q\337\352\223\017\311\267\300\000\000\001\017\000\000\000\assh-rsa\000\000\001\000\
264\273\211\254xSi;!{\231\332\240\313\323$H\214\251\254\022l\036\264\240\221\346\023\021.4i\203\000\
035\036\3670\310\031\353\303\177\350\336jD8Ti\326{\332\2302d\305#\2104\032~@HD\250\350ka\306[\370\37
5?\350\273c\363\240$\364z\000&\v\020\233\240\3738\234g\242\260\277B(;\372<\372Z\230C\0056\317$\246\3
13\306\373P4\252\200\367\360\205\236\217\233\221S\t\217\332\235\271\027\345\232\326b/\313\032u\005\3
54N\0366\317\020\304\326_\r\225\303\\L\201+\216\034\305\036]\346\302|\230\201\264\217!\366X\336%A\37
3k\v;'\200\210\224\0100F\311\313(\246\355\225\340\234\021\037\006'zu2R\333&\365\v-\355\f\327\\\216\2
73;\214\237)R\305,(<j\305\237O\366\2556M\027NV\264\373\277\330{\321\343\v_O\326\261]Q\366\246N\350\2
553[\002e~\004"
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: got packet of type 33
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: sending message >>"\025"<<
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: waiting for packet from server...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: packet length(12) remain
ing(8)
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.incoming_packet_stream: received: "\025"
[DEBUG] Sun Dec 09 04:34:31 -0800 2007 -- transport.session: got packet of type 21
OpenSSL::Cipher::Cipher:42: initialize arg: (12)[des-ede3-cbc]
OpenSSL::Cipher::Cipher:42: encrypt: (0)[]
OpenSSL::Cipher::Cipher:42: iv_len: [8]
OpenSSL::Cipher::Cipher:42: iv =
½]8)[úP?ìuì
OpenSSL::Cipher::Cipher:42: key_len: [24]
OpenSSL::Cipher::Cipher:42: key =
](24)[¦*?p+¶é(ó ?ç?,¶J¦+c?)5G
OpenSSL::Cipher::Cipher:44: initialize arg: (12)[des-ede3-cbc]
OpenSSL::Cipher::Cipher:44: decrypt: (0)[]
OpenSSL::Cipher::Cipher:44: iv_len: [8]
OpenSSL::Cipher::Cipher:44: iv =
 (8)[µ£q+rF+L]
OpenSSL::Cipher::Cipher:44: key_len: [24]
OpenSSL::Cipher::Cipher:44: key =
 (24)[¦T{¦UG++Gª+ SHnº(bf?5l]ï]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.session: sending message >>"\005\000\000\000\fss
h-userauth"<<
OpenSSL::Cipher::Cipher:42: block_size: [8]
OpenSSL::Cipher::Cipher:42: block_size: [8]
OpenSSL::Cipher::Cipher:42: block_size: [8]
OpenSSL::Cipher::Cipher:42: update arg:
 (32)[   ?
?   ?ssh-userauth?Çdî=?cKvG]
OpenSSL::Cipher::Cipher:42: update result:
 (32)[?+ëG+¦+¦¤6=6ä- Ö¯V+a¥AƦsÖY2+@ܵ*]
OpenSSL::Cipher::Cipher:42: final: (0)[]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.session: waiting for packet from server...
OpenSSL::Cipher::Cipher:44: block_size: [8]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
OpenSSL::Cipher::Cipher:44: block_size: [8]
OpenSSL::Cipher::Cipher:44: update arg:
 (8)[ª-P="@+A]
OpenSSL::Cipher::Cipher:44: update result:
 (8)[   ?
?  ]
OpenSSL::Cipher::Cipher:44: block_size: [8]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.incoming_packet_stream: packet length(28) remain
ing(24)
OpenSSL::Cipher::Cipher:44: update arg:
ù?¦9?TÿÆM- 8? QGi?'Äú¦ëX]
OpenSSL::Cipher::Cipher:44: update result:
 (24)[ ?ssh-userauth¥{¦M?+7?+?]
OpenSSL::Cipher::Cipher:44: final: (0)[]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.incoming_packet_stream: received: "\006\000\000\
000\fssh-userauth"
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.session: got packet of type 6
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- userauth.driver: trying "password"
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.session: sending message >>"2\000\000\000\016MYU
SERNAMEXXXX\000\000\000\016ssh-connection\000\000\000\010password\000\000\000\000\010MYPASSWD"<<
OpenSSL::Cipher::Cipher:42: block_size: [8]
OpenSSL::Cipher::Cipher:42: block_size: [8]
OpenSSL::Cipher::Cipher:42: update arg:
 (72)[   D?2   ?MYUSERNAMEXXXX   ?ssh-connection password  MYPASSWD+8?4+]
OpenSSL::Cipher::Cipher:42: update result:
 (72)[A.Ü[+?-°-§iI+?+n+²-?ÿO=-@<n%¦O94£â+ÑF_Ém+T(%²o&8÷¿¦ÿ+9?+«<dæ+hS˜Æ#²C?k?]
OpenSSL::Cipher::Cipher:42: final: (0)[]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.session: waiting for packet from server...
OpenSSL::Cipher::Cipher:44: block_size: [8]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.incoming_packet_stream: reading 8 bytes from soc
ket...
OpenSSL::Cipher::Cipher:44: block_size: [8]
OpenSSL::Cipher::Cipher:44: update arg:
 (8)[/+p?ë?ò¡]
OpenSSL::Cipher::Cipher:44: update result:
 (8)[ÅùVt¦?^¶]
OpenSSL::Cipher::Cipher:44: block_size: [8]
[DEBUG] Sun Dec 09 04:34:32 -0800 2007 -- transport.incoming_packet_stream: packet length(2409059956
) remaining(2409059952)
NativeException: java.lang.NegativeArraySizeException: null
        from ByteList.java:66:in `org.jruby.util.ByteList.<init>'
        from IOHandlerNio.java:266:in `org.jruby.util.IOHandlerNio.read'
        from RubyIO.java:1212:in `org.jruby.RubyIO.read'
        from null:-1:in `org.jruby.RubyIOInvoker$read_method_0_0.call'
        from CallSite.java:144:in `org.jruby.runtime.CallSite$InlineCachingCallSite.call'
        from CallSite.java:103:in `org.jruby.runtime.CallSite$ArgumentBoxingCallSite.call'
        from ASTInterpreter.java:653:in `org.jruby.evaluator.ASTInterpreter.callNode'
        from ASTInterpreter.java:300:in `org.jruby.evaluator.ASTInterpreter.evalInternal'
        from ASTInterpreter.java:2158:in `org.jruby.evaluator.ASTInterpreter.setupArgs'
        from ASTInterpreter.java:645:in `org.jruby.evaluator.ASTInterpreter.callNode'
        from ASTInterpreter.java:300:in `org.jruby.evaluator.ASTInterpreter.evalInternal'
        from ASTInterpreter.java:627:in `org.jruby.evaluator.ASTInterpreter.blockNode'
        from ASTInterpreter.java:294:in `org.jruby.evaluator.ASTInterpreter.evalInternal'
        from ASTInterpreter.java:1765:in `org.jruby.evaluator.ASTInterpreter.whileNode'
        from ASTInterpreter.java:480:in `org.jruby.evaluator.ASTInterpreter.evalInternal'
        from ASTInterpreter.java:627:in `org.jruby.evaluator.ASTInterpreter.blockNode'
... 267 levels...
        from C:/jruby/trunk/lib/ruby/gems/1.8/gems/net-ssh-1.1.2/lib/net/ssh/transport/session.rb:26
5:in `wait_for_message'
        from C:/jruby/trunk/lib/ruby/gems/1.8/gems/net-ssh-1.1.2/lib/net/ssh/transport/session.rb:25
8:in `loop'
        from C:/jruby/trunk/lib/ruby/gems/1.8/gems/net-ssh-1.1.2/lib/n


 All   Comments   Work Log   Change History      Sort Order: Ascending order - Click to sort in descending order
Bill Dortch - 09/Dec/07 07:37 AM
I should mention, you'll need to install Net::SSH (gem install net-ssh) to run the repro code.

Charles Oliver Nutter - 12/May/08 01:39 PM
Any updates on this Bill? JOpenSSL has obviously had some work recently and may work fine now.

Ola Bini - 13/Aug/08 07:37 AM
OK, I know one thing that is REALLY wrong now. It seems that when "final" is called on the Cipher object, MRI uses EVP_CipherFinal_ex. That's fine, the problem is that the context isn't actually cleaned up afterwards. Specifically, the documentation for the EVP_*Final methods say that that context should NOT be used again. Net::SSH does use the same Cipher context again, within reiniting it. So the problem is that OUR implementation of Cipher reinits itself at doFinal, which MRI doesn't do.

The result? Different IV's are used in subsequent encryptions with the same object. The initial IV is just that, an initial IV. I'll see if I can emulate this behavior in some way, but the question is if this is a bug in MRI, Net::SSH, or not at all. =/


Ola Bini - 13/Aug/08 08:17 AM
OK, this has been fixed on trunk. The main problem was the accidental usage of older operations results as the new IV. I'm now mimicking that disgusting behavior both in encryption and decryption. I've also fixed a few other problems that made Net::SSH 2 not start up (such as not recognizing DSS1withDSA as a Signature.)