Bug ID: JDK-8014272 jTDS JDBC SSL connections hang with JRE 6u34 and 7u6

JDK-8014272 : jTDS JDBC SSL connections hang with JRE 6u34 and 7u6

Type: Bug
Component: security-libs
Affected Version: 6u34,7u13,8

Priority: P3
Status: Resolved
Resolution: Not an Issue

Submitted: 2013-04-04
Updated: 2014-11-17
Resolved: 2013-05-17

Related Reports

Duplicate :	JDK-8015012 - jTDS JDBC driver not connecting after update to 1.6.0_34
Duplicate :	JDK-8014273 - Connection failure with SQL Server " Force Encryption " for Java6 U34-35 & 7U6-7

Description

FULL PRODUCT VERSION :
java -version
java version  " 1.7.0_13 " 
Java(TM) SE Runtime Environment (build 1.7.0_13-b20)
Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)


ADDITIONAL OS VERSION INFORMATION :
Linux 3.6.11-1-ARCH #1 SMP PREEMPT Tue Dec 18 08:57:15 CET 2012 x86_64 GNU/Linux

EXTRA RELEVANT SYSTEM CONFIGURATION :
IPv4 only, SQL Server installed on a remote system, firewalls disabled

A DESCRIPTION OF THE PROBLEM :
With recent versions of JRE 1.6 and 1.7, the jTDS driver is hanging after login when SSL is used. We have reproduced this using Java 1.6.0_39 and 1.7.0_13, with and without the JCE applied (we normally use the JCE for our application). Note that when we use earlier versions of the JREs, such as 1.6.0_27 or 1.7.0_5, this problem does not occur. In order to make sure the problem did not lie with our application, we wrote a small Groovy app that reproduces it without any extra stuff.

Note that we have tried using jTDS versions 1.2.7 (with Java 1.6), and 1.3.0 (with Java 1.7), and experience the same behavior of a hanging connection.

If we set -Djsse.enableCBCProtection=false, then the connection works as expected without hanging. However, that is not a workaround that we can use moving forward, due to the security risk.

Is this a problem with the JRE, or a problem with jTDS?

REGRESSION.  Last worked in version 7

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Attempt to open a JDBC connect to SQL Server using jTDS. It hangs. Although the example code below is written using Groovy, we have also seen this bug in our pure Java application.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
jTDS should function normally, where SQL queries can be sent to the database, and return a response.
ACTUAL -
When we enable -Djavax.net.debug=all, the last few packets exchanged are:

Set collation to 0x0904E00000/Cp1252
Language changed from  to us_english
SQLWarning: reason(Changed language setting to us_english.) SQLState(01000) vendor code(5703)
Changed blocksize to 4096
----- Stream #2 send last Request packet

   0: 01 01 01 38 00 00 01 00 53 00 45 00 4C 00 45 00 |   8    S E L E |
  16: 43 00 54 00 20 00 40 00 40 00 4D 00 41 00 58 00 |C T   @ @ M A X |
  32: 5F 00 50 00 52 00 45 00 43 00 49 00 53 00 49 00 |_ P R E C I S I |
  48: 4F 00 4E 00 0D 00 0A 00 53 00 45 00 54 00 20 00 |O N     S E T   |
  64: 54 00 52 00 41 00 4E 00 53 00 41 00 43 00 54 00 |T R A N S A C T |
  80: 49 00 4F 00 4E 00 20 00 49 00 53 00 4F 00 4C 00 |I O N   I S O L |
  96: 41 00 54 00 49 00 4F 00 4E 00 20 00 4C 00 45 00 |A T I O N   L E |
 112: 56 00 45 00 4C 00 20 00 52 00 45 00 41 00 44 00 |V E L   R E A D |
 128: 20 00 43 00 4F 00 4D 00 4D 00 49 00 54 00 54 00 |  C O M M I T T |
 144: 45 00 44 00 0D 00 0A 00 53 00 45 00 54 00 20 00 |E D     S E T   |
 160: 49 00 4D 00 50 00 4C 00 49 00 43 00 49 00 54 00 |I M P L I C I T |
 176: 5F 00 54 00 52 00 41 00 4E 00 53 00 41 00 43 00 |_ T R A N S A C |
 192: 54 00 49 00 4F 00 4E 00 53 00 20 00 4F 00 46 00 |T I O N S   O F |
 208: 46 00 0D 00 0A 00 53 00 45 00 54 00 20 00 51 00 |F     S E T   Q |
 224: 55 00 4F 00 54 00 45 00 44 00 5F 00 49 00 44 00 |U O T E D _ I D |
 240: 45 00 4E 00 54 00 49 00 46 00 49 00 45 00 52 00 |E N T I F I E R |
 256: 20 00 4F 00 4E 00 0D 00 0A 00 53 00 45 00 54 00 |  O N     S E T |
 272: 20 00 54 00 45 00 58 00 54 00 53 00 49 00 5A 00 |  T E X T S I Z |
 288: 45 00 20 00 32 00 31 00 34 00 37 00 34 00 38 00 |E   2 1 4 7 4 8 |
 304: 33 00 36 00 34 00 37 00                         |3 6 4 7 |

Padded plaintext before ENCRYPTION:  len = 32
0000: 01 DD FA 88 D0 7C 40 44   7F EA 49 E1 A2 AD D6 AF  ......@D..I.....
0010: 1E 01 4B 24 5E 0A 0A 0A   0A 0A 0A 0A 0A 0A 0A 0A  ..K$^...........
main, WRITE: TLSv1 Application Data, length = 32
[Raw write]: length = 37
0000: 17 03 01 00 20 63 05 9C   6C 21 C6 BE F6 4C FC 17  .... c..l!...L..
0010: C1 C0 F3 6A 3E 6F 5A DF   A6 78 B5 91 85 AE E2 F6  ...j>oZ..x......
0020: D9 65 1D A8 2A                                     .e..*
Padded plaintext before ENCRYPTION:  len = 336
0000: 01 01 38 00 00 01 00 53   00 45 00 4C 00 45 00 43  ..8....S.E.L.E.C
0010: 00 54 00 20 00 40 00 40   00 4D 00 41 00 58 00 5F  .T. .@.@.M.A.X._
0020: 00 50 00 52 00 45 00 43   00 49 00 53 00 49 00 4F  .P.R.E.C.I.S.I.O
0030: 00 4E 00 0D 00 0A 00 53   00 45 00 54 00 20 00 54  .N.....S.E.T. .T
0040: 00 52 00 41 00 4E 00 53   00 41 00 43 00 54 00 49  .R.A.N.S.A.C.T.I
0050: 00 4F 00 4E 00 20 00 49   00 53 00 4F 00 4C 00 41  .O.N. .I.S.O.L.A
0060: 00 54 00 49 00 4F 00 4E   00 20 00 4C 00 45 00 56  .T.I.O.N. .L.E.V
0070: 00 45 00 4C 00 20 00 52   00 45 00 41 00 44 00 20  .E.L. .R.E.A.D.
0080: 00 43 00 4F 00 4D 00 4D   00 49 00 54 00 54 00 45  .C.O.M.M.I.T.T.E
0090: 00 44 00 0D 00 0A 00 53   00 45 00 54 00 20 00 49  .D.....S.E.T. .I
00A0: 00 4D 00 50 00 4C 00 49   00 43 00 49 00 54 00 5F  .M.P.L.I.C.I.T._
00B0: 00 54 00 52 00 41 00 4E   00 53 00 41 00 43 00 54  .T.R.A.N.S.A.C.T
00C0: 00 49 00 4F 00 4E 00 53   00 20 00 4F 00 46 00 46  .I.O.N.S. .O.F.F
00D0: 00 0D 00 0A 00 53 00 45   00 54 00 20 00 51 00 55  .....S.E.T. .Q.U
00E0: 00 4F 00 54 00 45 00 44   00 5F 00 49 00 44 00 45  .O.T.E.D._.I.D.E
00F0: 00 4E 00 54 00 49 00 46   00 49 00 45 00 52 00 20  .N.T.I.F.I.E.R.
0100: 00 4F 00 4E 00 0D 00 0A   00 53 00 45 00 54 00 20  .O.N.....S.E.T.
0110: 00 54 00 45 00 58 00 54   00 53 00 49 00 5A 00 45  .T.E.X.T.S.I.Z.E
0120: 00 20 00 32 00 31 00 34   00 37 00 34 00 38 00 33  . .2.1.4.7.4.8.3
0130: 00 36 00 34 00 37 00 CC   2B 17 A6 64 92 C0 4C 55  .6.4.7..+..d..LU
0140: C9 B0 2B 15 C5 22 A6 B9   AA 19 58 04 04 04 04 04  ..+.. " ....X.....
main, WRITE: TLSv1 Application Data, length = 336
[Raw write]: length = 341
0000: 17 03 01 01 50 FE ED 12   F7 DE 64 3E A0 F4 CA CC  ....P.....d>....
0010: DE BC 31 A2 2C E1 5B 9C   91 07 7F DB A4 D9 4E CC  ..1.,.[.......N.
0020: 43 9E 42 E1 6B 1E 29 C9   35 39 D0 C9 CA 55 92 B7  C.B.k.).59...U..
0030: D8 78 C9 15 A6 7F 2C 33   9B C4 B7 78 B3 AD E6 04  .x....,3...x....
0040: EE 00 F4 22 88 9B D1 9A   61 83 3D 16 72 DF A7 DE  ... " ....a.=.r...
0050: 88 D8 8B A1 96 33 4A F4   8B 79 CD 94 21 AF 4F FA  .....3J..y..!.O.
0060: BB 5C E7 8B 7A 75 E5 26   0E B3 1A 21 AE AC B6 D4  .\..zu.&...!....
0070: 05 D4 C4 9A 51 FC 21 5A   29 FE 72 CD 99 8B 8E 30  ....Q.!Z).r....0
0080: EB 4F 60 4C 76 9C 3D D7   E2 69 3E AC 52 42 E3 C2  .O`Lv.=..i>.RB..
0090: EB A2 21 D0 6A C7 C6 84   54 59 82 B1 9C FE 55 27  ..!.j...TY....U'
00A0: 60 7C A7 25 CD FC C1 5A   C9 D3 5A 47 56 FB 55 C7  `..%...Z..ZGV.U.
00B0: 6F EA DC 84 56 7E 48 E9   F5 7E AE 25 19 5F CF 3F  o...V.H....%._.?
00C0: 11 DC AD 0B EE 46 74 5F   D7 08 9D 04 D3 5F 56 71  .....Ft_....._Vq
00D0: DF 7B FA AE ED 36 22 F8   FA 15 3A A9 DF 59 8D DE  .....6 " ...:..Y..
00E0: 66 D7 D2 6A 57 DC CA 33   14 39 35 96 16 DF 98 25  f..jW..3.95....%
00F0: E1 DD A4 EF B9 CA 78 E6   79 0D 4F 72 80 2C F3 8D  ......x.y.Or.,..
0100: 02 A6 F4 34 8F 98 59 63   D8 9B 51 A1 39 D9 26 00  ...4..Yc..Q.9.&.
0110: DC 1C BF 51 EA B1 E9 8C   35 5F 5D 91 1A E5 D4 50  ...Q....5_]....P
0120: 83 AC FE 92 E5 4D B8 40   0F 08 2E 71 DC D9 51 78  .....M.@...q..Qx
0130: F9 51 6C 83 5F CF 9E 75   E1 60 DF C2 8D BC 0D 33  .Ql._..u.`.....3
0140: 65 79 9B FF 71 F2 9F FE   B3 B9 DA B7 8E 17 4F 1B  ey..q.........O.
0150: 83 76 52 3F 85                                     .vR?.

The precision check is the very first SQL query issued by jTDS after logging in (which happens after the SSL handshake).

Note that this looks very similar to the BEAST SSL issue, however this is reproduced using Java versions that include the fix, and affect SQL Server database that have been patched (2008 R2 and 2012).

ERROR MESSAGES/STACK TRACES THAT OCCUR :
If we take a thread dump when the connection is hanging, we can see the following:

2013-02-07 16:04:07
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.7-b01 mixed mode):

 " Monitor Ctrl-Break "  daemon prio=10 tid=0x00007fc9a8181800 nid=0x735c runnable [0x00007fc997541000]
   java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
- locked <0x00000000d71516a0> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:154)
at java.io.BufferedReader.readLine(BufferedReader.java:317)
- locked <0x00000000d71516a0> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:382)
at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:85)
at java.lang.Thread.run(Thread.java:722)

 " Service Thread "  daemon prio=10 tid=0x00007fc9a80ef800 nid=0x735a runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

 " C2 CompilerThread1 "  daemon prio=10 tid=0x00007fc9a80ed800 nid=0x7359 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

 " C2 CompilerThread0 "  daemon prio=10 tid=0x00007fc9a80ea800 nid=0x7358 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

 " Signal Dispatcher "  daemon prio=10 tid=0x00007fc9a80e8000 nid=0x7357 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

 " Finalizer "  daemon prio=10 tid=0x00007fc9a809b000 nid=0x7356 in Object.wait() [0x00007fc997ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d70b5798> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000000d70b5798> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

 " Reference Handler "  daemon prio=10 tid=0x00007fc9a8099000 nid=0x7355 in Object.wait() [0x00007fc9a414b000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d70b5320> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x00000000d70b5320> (a java.lang.ref.Reference$Lock)

 " main "  prio=10 tid=0x00007fc9a8008800 nid=0x734f runnable [0x00007fc9b0601000]
   java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at net.sourceforge.jtds.ssl.TdsTlsInputStream.read(TdsTlsInputStream.java:72)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:312)
at sun.security.ssl.InputRecord.read(InputRecord.java:350)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)
- locked <0x00000000d849f9b0> (a java.lang.Object)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:884)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
- locked <0x00000000d8915910> (a sun.security.ssl.AppInputStream)
at java.io.DataInputStream.readFully(DataInputStream.java:195)
at java.io.DataInputStream.readFully(DataInputStream.java:169)
at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:881)
at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:762)
- locked <0x00000000d8330338> (a java.util.concurrent.ConcurrentHashMap)
at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:477)
at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:114)
at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:99)
at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3999)
at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1052)
- locked <0x00000000d8a1f308> (a net.sourceforge.jtds.jdbc.TdsCore)
at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:493)
at net.sourceforge.jtds.jdbc.JtdsStatement.executeQuery(JtdsStatement.java:1427)
at net.sourceforge.jtds.jdbc.JtdsConnection.<init>(JtdsConnection.java:414)
at net.sourceforge.jtds.jdbc.Driver.connect(Driver.java:183)
at java.sql.DriverManager.getConnection(DriverManager.java:579)
at java.sql.DriverManager.getConnection(DriverManager.java:190)
at groovy.sql.Sql.newInstance(Sql.java:312)
at groovy.sql.Sql.newInstance(Sql.java:356)
at groovy.sql.Sql$newInstance.call(Unknown Source)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at com.broken.jdbc.BugMain.main(BugMain.groovy:27)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)

 " VM Thread "  prio=10 tid=0x00007fc9a8091800 nid=0x7354 runnable

 " GC task thread#0 (ParallelGC) "  prio=10 tid=0x00007fc9a8016000 nid=0x7350 runnable

 " GC task thread#1 (ParallelGC) "  prio=10 tid=0x00007fc9a8018000 nid=0x7351 runnable

 " GC task thread#2 (ParallelGC) "  prio=10 tid=0x00007fc9a8019800 nid=0x7352 runnable

 " GC task thread#3 (ParallelGC) "  prio=10 tid=0x00007fc9a801b800 nid=0x7353 runnable

 " VM Periodic Task Thread "  prio=10 tid=0x00007fc9a8102800 nid=0x735b waiting on condition

JNI global references: 155

Heap
 PSYoungGen      total 36736K, used 26475K [0x00000000d70b0000, 0x00000000d99a0000, 0x0000000100000000)
  eden space 31552K, 83% used [0x00000000d70b0000,0x00000000d8a8ac60,0x00000000d8f80000)
  from space 5184K, 0% used [0x00000000d9490000,0x00000000d9490000,0x00000000d99a0000)
  to   space 5184K, 0% used [0x00000000d8f80000,0x00000000d8f80000,0x00000000d9490000)
 ParOldGen       total 83904K, used 0K [0x0000000085200000, 0x000000008a3f0000, 0x00000000d70b0000)
  object space 83904K, 0% used [0x0000000085200000,0x0000000085200000,0x000000008a3f0000)
 PSPermGen       total 21248K, used 11660K [0x0000000080000000, 0x00000000814c0000, 0x0000000085200000)
  object space 21248K, 54% used [0x0000000080000000,0x0000000080b633d0,0x00000000814c0000)

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
package com.broken.jdbc

import groovy.sql.Sql

class BugMain {
    public static void main(String[] args) {

        def properties = new Properties()
        properties.setProperty( " ssl " ,  " require " )
        properties.setProperty( " password " ,  " <mypassword> " )
        properties.setProperty( " user " ,  " <myuser> " )

        Sql sql = Sql.newInstance( " jdbc:jtds:sqlserver://<myhost>/<mydbname> " , properties,  " net.sourceforge.jtds.jdbc.Driver " )
    }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
If we set -Djsse.enableCBCProtection=false, then the connection works as expected without hanging. However, that is not a workaround that we can use moving forward, due to the security risk.

Comments

I updated the synopsis to be indicate when the issue was introduced. This information came from JDK-8014723.
30-05-2013
I am almost positive that this is BEAST related, it has every symptom. The BEAST issue affects 6u27 and before, which is exactly inline with the report. However, it doesn't quite make sense about 7u5. I have a vague recollection that we fixed a ordering issue that may change the order of ciphersuites, which may be causing this problem only on 7u5? (edited: this is a red herring, please see below.) Regardless, the stacktrace shows the code is hanging in the read of the Socket, which indicates that the Remote side has not sent anything yet. We've had many bugs like this, where the peer is not completely reading the request. All I/O code needs to properly handle packet fragmentation, either at the TCP or SSL layer. For example: if (is.read(b) != -1) { parse(b).doAction(); } but if only one byte of b is present, doAction may stall waiting for the complete command that it is expecting to be in b.
17-05-2013
Also see JDK-8014273. It has more detailed information about the affected versions, which are 6u34 and 7u6. Here's the dump files. Looking at the dumps, some things to notice: 1. This has every indication of being caused by: JDK-7157903: JSSE client sockets are very slow (Nagle's) which was fixed in 6u34/7u6. In 7u1->7u5, we were shipping each SSL packet in one TCP packet. We are now shipping two SSL packets in one TCP packet to avoid running afoul of Nagle's, and something isn't handling that very well. The customer's MS's SQL Server was known to work with 7u5 which means it has the BEAST fix on both sides. Very likely it can't handle this new optimization. 2. jTDS is known to do some packet rewriting due to the TDS format, so it's possible that something in there is wrong, but it appears that once encryption starts, TDS is passed inside the TLS, not outside like before handshake is complete. 3. If you look at the client list of ciphersuites, they are in a slightly different order, which is the result of: JDK-7174244: NPE in Krb5ProxyImpl.getServerKeys() where we switched from using a ArrayList to a TreeSet, which uses natural ordering inside the CipherSuite using compareTo() instead of values() which will iterate in some random order. 4. The ciphersuite in both connections is a block cipher. TLS_RSA_WITH_AES_128_CBC_SHA. 5. The handshaking is identical except for hashes/nonces. 6. App data: The data transfer is similar, except for a few bytes at the end of each packet. Timestamp maybe? I'm pretty convinced that this is an issue with MS SQL. It needs to handle packet splitting at both the TLS and SSL layers. I will be mentioning this to management, and hopefully they will be able to inform MS support.
17-05-2013
Sending a note to the customer to see if I can get debug output. This may be related to JDK-7174244.
15-05-2013