Intermittent connection failure with Microsoft SQL Server JDBC driver

Question

Intermittent connection failure with Microsoft SQL Server JDBC driver

I got an intermittent connection error with the Microsoft SQL Server JDBC driver. I recently added a config to the java.util.logging system and was able to capture both successful and failed connections using the same code and environment.

On failure, I see this sequence of log messages:

Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection <init>
FINE: ConnectionID:1 created by (SQLServerDriver:3)
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINER: ConnectionID:1 Start time: 1433173352072 Time out time: 1433173367072 Timeout Unit Interval: 15000
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt server name: aws-db1-ws2008r2.datical.net port: 1444 InstanceName: null useParallel: false
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt endtime: 1433173367072
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt No: 0
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.SQLServerConnection connectHelper
FINE: ConnectionID:1 Connecting with server: aws-db1-ws2008r2.datical.net port: 1444 Timeout slice: 14597 Timeout Full: 15
Jun 01, 2015 3:42:32 PM com.microsoft.sqlserver.jdbc.TDSChannel open
FINER: TDSChannel (ConnectionID:1): Opening TCP socket...
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 Requesting encryption level:OFF
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 ActivityId ba082894-01df-4c7a-bcd3-8519c6a05d59-1
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINE: ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 Server returned major version:11
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 Negotiated encryption level:OFF
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 Ignoring prelogin response option:5
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) Enabling SSL...
Jun 01, 2015 3:42:34 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) SSL handshake will trust any certificate
Jun 01, 2015 4:04:04 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) Starting SSL handshake
Jun 01, 2015 4:04:04 PM com.microsoft.sqlserver.jdbc.TDSChannel write
FINER: TDSChannel (ConnectionID:1) write failed:Connection reset by peer: socket write error
Jun 01, 2015 4:04:04 PM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: *** SQLException:ConnectionID:1 ClientConnectionId: 25ce5505-c111-4fde-a135-7a55ce503be7 com.microsoft.sqlserver.jdbc.SQLServerException: Connection reset by peer: socket write error ClientConnectionId:25ce5505-c111-4fde-a135-7a55ce503be7 Connection reset by peer: socket write error ClientConnectionId:25ce5505-c111-4fde-a135-7a55ce503be7
Jun 01, 2015 4:04:04 PM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1667)com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1654)com.microsoft.sqlserver.jdbc.TDSChannel.write(IOBuffer.java:1805)com.microsoft.sqlserver.jdbc.TDSWriter.flush(IOBuffer.java:3581)com.microsoft.sqlserver.jdbc.TDSWriter.writePacket(IOBuffer.java:3482)com.microsoft.sqlserver.jdbc.TDSWriter.endMessage(IOBuffer.java:3062)com.microsoft.sqlserver.jdbc.TDSChannel$SSLHandshakeOutputStream.endMessage(IOBuffer.java:770)com.microsoft.sqlserver.jdbc.TDSChannel$SSLHandshakeInputStream.ensureSSLPayload(IOBuffer.java:633)com.microsoft.sqlserver.jdbc.TDSChannel$SSLHandshakeInputStream.readInternal(IOBuffer.java:708)com.microsoft.sqlserver.jdbc.TDSChannel$SSLHandshakeInputStream.read(IOBuffer.java:700)com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:895)com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.read(IOBuffer.java:883)sun.security.ssl.InputRecord.readFully(InputRecord.java:442)sun.security.ssl.InputRecord.read(InputRecord.java:480)sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1312)sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1339)sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1323)com.microsoft.sqlserver.jdbc.TDSChannel.enableSSL(IOBuffer.java:1618)com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:1323)com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:991)com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:827)com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:1012)com.datical.hammer.core.connectionservice.DatabaseBuilder.createDatabaseObject(DatabaseBuilder.java:217)com.datical.hammer.core.connectionservice.DatabaseBuilder.buildDatabase(DatabaseBuilder.java:130)com.datical.hammer.core.connectionservice.DatabaseBuilder.buildConnection(DatabaseBuilder.java:56)com.datical.hammer.integration.TeztUtils.testConnection(TeztUtils.java:704)com.datical.hammer.integration.Databases.printActivatedDbs(Databases.java:219)com.datical.hammer.integration.Databases.<clinit>(Databases.java:193)com.datical.hammer.integration.AllTheseChangeLogsOnExistingDBShouldPassForecastTest.parameters(AllTheseChangeLogsOnExistingDBShouldPassForecastTest.java:94)sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)java.lang.reflect.Method.invoke(Method.java:606)org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)org.junit.runners.Parameterized.allParameters(Parameterized.java:292)org.junit.runners.Parameterized.<init>(Parameterized.java:282)sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)java.lang.reflect.Constructor.newInstance(Constructor.java:526)org.junit.internal.builders.AnnotatedBuilder.buildRunner(AnnotatedBuilder.java:29)org.junit.internal.builders.AnnotatedBuilder.runnerForClass(AnnotatedBuilder.java:21)org.junit.runners.model.RunnerBuilder.safeRunnerForClass(RunnerBuilder.java:59)org.junit.internal.builders.AllDefaultPossibilitiesBuilder.runnerForClass(AllDefaultPossibilitiesBuilder.java:26)org.junit.runners.model.RunnerBuilder.safeRunnerForClass(RunnerBuilder.java:59)org.junit.internal.requests.ClassRequest.getRunner(ClassRequest.java:26)org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:262)org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
Jun 01, 2015 4:04:04 PM com.microsoft.sqlserver.jdbc.SQLServerConnection:1 close
FINER: ENTRY

Whereas on success I see this sequence:

Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection <init>
FINE: ConnectionID:1 created by (SQLServerDriver:3)
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINER: ConnectionID:1 Start time: 1433175882745 Time out time: 1433175897745 Timeout Unit Interval: 15000
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt server name: aws-db1-ws2008r2.datical.net port: 1444 InstanceName: null useParallel: false
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt endtime: 1433175897745
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt No: 0
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.SQLServerConnection connectHelper
FINE: ConnectionID:1 Connecting with server: aws-db1-ws2008r2.datical.net port: 1444 Timeout slice: 14982 Timeout Full: 15
Jun 01, 2015 4:24:42 PM com.microsoft.sqlserver.jdbc.TDSChannel open
FINER: TDSChannel (ConnectionID:1): Opening TCP socket...
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 15848334-e973-4c17-ad0f-79ebf0f4e9da Requesting encryption level:OFF
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 15848334-e973-4c17-ad0f-79ebf0f4e9da ActivityId 22b9780e-325e-4057-8a34-845c7024a2eb-1
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINE: ConnectionID:1 ClientConnectionId: 15848334-e973-4c17-ad0f-79ebf0f4e9da Server returned major version:11
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 15848334-e973-4c17-ad0f-79ebf0f4e9da Negotiated encryption level:OFF
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINER: ConnectionID:1 ClientConnectionId: 15848334-e973-4c17-ad0f-79ebf0f4e9da Ignoring prelogin response option:5
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) Enabling SSL...
Jun 01, 2015 4:24:43 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) SSL handshake will trust any certificate
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) Starting SSL handshake
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel$PermissiveX509TrustManager checkServerTrusted
FINER: TDSChannel (ConnectionID:1) (PermissiveX509TrustManager): Trusting server certificate
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel enableSSL
FINER: TDSChannel (ConnectionID:1) SSL enabled
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel disableSSL
FINER: TDSChannel (ConnectionID:1) Disabling SSL...
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel disableSSL
FINER: TDSChannel (ConnectionID:1) Closing SSL socket
Jun 01, 2015 4:24:47 PM com.microsoft.sqlserver.jdbc.TDSChannel disableSSL
FINER: TDSChannel (ConnectionID:1) SSL disabled

One thing that is particularly annoying is that it takes a long time when it fails - notice the 22+ minute gap from 3:42:34 to 4:04:04 in the crash log.

EDIT I decided to wrap the method call connect()

in Callable

and use the Guava class SimpleTimeLimiter

so that it doesn't hang for that long. If it connects, it will connect quickly. I also introduced a retry loop to retry the connection 5 times. I'll give my integration tests tonight and see what happens.

UPDATE Adding timeout and re-logic didn't help. As noted in the comment below, I noticed that when this code is running from a Jenkins slave (running as a Windows service, logged in as a Jenkins user), the connection fails ~ 90% of the time and succeeds the other 10%. If I am using remote desktop and login as "Jenkins" then run the same command from command line, it serially connects without issue. Setting the system property javax.net.debug=all

shows that after these two messages a "hang" occurs:

trigger seeding of SecureRandom
done seeding SecureRandom

If successful, these messages are followed by messages related to SSL handshaking, including a list of unavailable cipher suites and a message Is initial handshake: true

+3

java sql-server jdbc

SteveDonie 01 june 15 at 17:28

source to share