3

here an error which drives me crazy, which seems to have tons of related entries but non solution worked so far. Maybe there is something special about my configuration I haven't found so far...

Im running a Java application, using Hibernation (5.0.3.Final) connected an Azure SQL DB (v12) via JNDI ressources (tomcat 8.0.28). I am receiving, as it looks randomly, Connection reset by peer: socket write error's followed by The connection is closed errors. The app does not recover until restart...

This happens despite the fact that i have configured a validationQuery and also set testOnCreate, testOnBorrow and testWhileIdle to true.

I'll give you the whole configuration below. This really drives me crazy as this seems to be a bug which is well known but not solved since years?!

Here's the configuration:

server.xml:

 <Resource name="jdbc/booking"
     global="jdbc/booking"
     auth="Container"
     username="XXX"
     password="YYY"
     type="javax.sql.XADataSource"
     driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver"
     url="jdbc:sqlserver://mydatabase.database.windows.net:1433;database=booking;encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;loginTimeout=30;"
     factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
     maxWait="10000"
     validationQuery="SELECT 1"
     testOnCreate="true"
     testOnBorrow="true"
     testWhileIdle="true"
     timeBetweenEvictionRunsMillis="30000"
     minEvictableIdleTimeMillis="60000"
     validationInterval="1000"
     removeAbandonedOnMaintenance="true"
     fastFailValidation="true"/>

context.xml (in web/META-INF/ of the war)

<ResourceLink name="jdbc/booking" global="jdbc/booking"/>

hibernate.cfg

<property name="connection.driver_class">com.microsoft.sqlserver.jdbc.SQLServerDriver</property>
<property name="connection.datasource">java:comp/env/jdbc/booking</property>

I'm setting up the Hibernate session factory like this:

private void setUp() {
    final StandardServiceRegistry registry = new StandardServiceRegistryBuilder().configure( AzureDB.configFile ).build();
    try {
        this.sessionFactory = new MetadataSources( registry ).buildMetadata().buildSessionFactory();
    } catch ( final Exception e ) {
        System.err.println( e.getMessage() );
        StandardServiceRegistryBuilder.destroy( registry );
        System.exit( 666 );
    }
}

and use it via injection in my services like this:

@Inject private AzureDB           bookingDB;

...

this.bookingDB.getCurrentSession().beginTransaction();
final Hotel hotel = this.bookingDB.getCurrentSession().get( Hotel.class, hotelId );

One request will finish successfully, the next will run into the Connection rest by peer error. A full stracktrace will look like this:

16-Nov-2015 09:26:59.028 WARN [http-apr-8080-exec-13] org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logExceptions SQL Error: 0, SQLState: 08S01
16-Nov-2015 09:26:59.028 ERROR [http-apr-8080-exec-13] org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logExceptions Connection reset by peer: socket write error
16-Nov-2015 09:26:59.044 INFO [http-apr-8080-exec-13] org.hibernate.event.internal.DefaultLoadEventListener.onLoad HHH000327: Error performing load command : org.hibernate.exception.JDBCConnectionException: could not extract ResultSet
16-Nov-2015 09:26:59.060 SEVERE [http-apr-8080-exec-13] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [com.nekst.service.nekstAPI] in context with path [] threw exception [org.hibernate.exception.JDBCConnectionException: could not extract ResultSet] with root cause
 com.microsoft.sqlserver.jdbc.SQLServerException: Connection reset by peer: socket write error
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1748)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1732)
    at com.microsoft.sqlserver.jdbc.TDSChannel.write(IOBuffer.java:1842)
    at com.microsoft.sqlserver.jdbc.TDSWriter.flush(IOBuffer.java:4161)
    at com.microsoft.sqlserver.jdbc.TDSWriter.writePacket(IOBuffer.java:4062)
    at com.microsoft.sqlserver.jdbc.TDSWriter.endMessage(IOBuffer.java:3107)
    at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:6700)
    at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:424)
    at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:372)
    at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:6276)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1793)
    at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:184)
    at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:159)
    at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery(SQLServerPreparedStatement.java:284)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:433)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:120)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:85)
    at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3954)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:488)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:453)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:196)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:258)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:134)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1071)
    at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:164)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2638)
    at org.hibernate.internal.SessionImpl.get(SessionImpl.java:955)
    at sun.reflect.GeneratedMethodAccessor160.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.hibernate.context.internal.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:338)
    at com.sun.proxy.$Proxy138.get(Unknown Source)
    at com.nekst.service.rest.Kauai.getLocation(Kauai.java:227)
    at com.nekst.service.rest.Kauai.getRecommendation(Kauai.java:65)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:471)
    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:425)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:383)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:336)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:223)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
    at com.googlecode.psiprobe.Tomcat80AgentValve.invoke(Tomcat80AgentValve.java:45)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2503)
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2492)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

followed by com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed. on any succeeding request.

There can be weeks of undisturbed service and then (like currently) I see this errors continuously... Has anybody experience in this concrete setting or any other remarks to my situation? Help is appreciated a lot...

UPDATE: I also tried adding custom registry entries as suggested here: https://msdn.microsoft.com/en-us/library/hh290696(v=SQL.110).aspx, no luck, I can see the keepalives in wireshark, but still getting those errors

gapvision
  • 999
  • 1
  • 10
  • 30
  • Can you establish a connection to the db? –  Nov 16 '15 at 10:07
  • yep, DB is up and running, the problem is solved immediately by restarting the service – gapvision Nov 16 '15 at 10:07
  • I vote my own question for closed because of "too broad". I see now that there are no solutions to this as there are too many possible reasons. Anyway, I found a solution for my problem: While wondering why the JDBC connection pool does not recycle the closed connection, I understood that is Hibernate who does not release the connection. Thats also the reason why `testOnBorrow` and similar mechanism didnt work. So searched and found the bug in my own implementation... – gapvision Nov 17 '15 at 15:56

2 Answers2

1

Per my experience, the issue was generally caused by using the unsuitable configuration for the JDBC connection pool in JNDI.

There is a offical doc for the Azure SQL Database resource limits https://azure.microsoft.com/en-us/documentation/articles/sql-database-resource-limits/.

I checked your JNDI configuration. So I suggest you can refer to your Azure service tier's limits and the Tomcat doc for JDBC data source settings in JNDI https://tomcat.apache.org/tomcat-7.0-doc/jndi-resources-howto.html#JDBC_Data_Sources to set the configuration properties initialSize, maxActive,minIdle and maxIdle to suitable values like maxIdle=100.

Update: enter image description here

The initialSize & minIdle default value is 0. The minIdle property control the pool connection minimal count when the pool release the connection with low concurrent access. If the pool connection released till 0, the new access will cause the issue connection reset.

Updated at 2015.11.19:

There is an excerpt explained the issue Connection reset by peer.

[10054] Connection reset by peer

Connection reset by peer is a tough one because it can be caused by so many things. In all cases, the server determines that the socket is no longer good and closes it from its side.

Write Error

Scenario: Mary was trying to talk to Joe but didn't think she was getting through, so she hung rather than lose his messages (data). A write error occurs when a server cannot successfully write to a user's client. When the server receives information, it usually responds with information of its own. When the server receives an error when writing to a client, it then disconnects the user, resulting in a write error quit message similar to the read error format.

Community
  • 1
  • 1
Peter Pan
  • 23,476
  • 4
  • 25
  • 43
  • I'm sorry I do not see the point of these settings as the standard values are `=10`. I can not discover any limit violated by this standard values nor do I know what _better_ values would be – gapvision Nov 17 '15 at 06:07
  • @gapvision The updated post explains the point of JDBC data source settings. And for the setting `maxIdle` & `maxActive`, according to the sql database resource limits to change greater suitably for performance. – Peter Pan Nov 18 '15 at 09:28
  • seems this standard values changed since 8.0: https://tomcat.apache.org/tomcat-8.0-doc/jdbc-pool.html Why should a connection pool cause an `connection reset` simply by hitting the lower boundaries of the pool size? In any case, the assumpted behavior would be to create a new connection whenever the current available connections do not suffice. – gapvision Nov 18 '15 at 19:09
  • @gapvision I update the post and add an exerpt explained this issue. – Peter Pan Nov 19 '15 at 07:49
  • 1
    thanks a lot for your effort, but I still don't see how this can be caused by hitting the pool boundaries? – gapvision Nov 19 '15 at 15:15
0

Try to set the Idle timeout value to some large value. Do you observe any pattern as to when this issue occurs? Is there a idle state after which you see this problem? Check - http://www.coderanch.com/t/633566/JDBC/databases/microsoft-sqlserver-jdbc-SQLServerException-Connection

This also explains the same behavior due to timeout - DBCP returns closed connections

Try to turn on the logging for the driver by following the link - https://msdn.microsoft.com/en-us/library/ms378517(v=SQL.110).aspx

Use the finest level logging and check if you can get the details of the problem.

Community
  • 1
  • 1
Prasad Kerhalkar
  • 36
  • 4