Thread leak + Unable to acquire JDBC Connection (Hibernate + Hikari + MySQL)

jnrbo commented 6 years ago

Environment

HikariCP version:        2.7.3
JDK version:             1.8.0_121
Database:                MySQL
Driver version:          x.x.x
Hibernate version:       5.1.10.Final
Tomcat version:          8.5.23

After a few hours running, my application stop working. I'm getting a few leak detections, but with no success figuring out how to fix it.

The error I get when stop working is:

ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - HikariPool-1 - Connection is not available, request timed out after 30004ms.
javax.persistence.PersistenceException: 

org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

Also, I'm getting a lot of logs when I perform any SELECT/UPDATE/INSERT (when showing a list, for example, there's 120x):

1985837 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Executed rollback on connection com.mysql.jdbc.JDBC4Connection@438b4b42 due to dirty commit state on close().

Active pool's only increases (total=27, active=22, idle=5, waiting=0).

HikariCP Startup log:

883 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - HikariPool-1 - configuration:
887 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
888 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................false
889 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
890 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
891 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
892 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
893 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
894 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
897 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
900 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{cacheServerConfiguration=true, useServerPrepStmts=true, cachePrepStmts=true, rewriteBatchedStatements=true, cacheResultSetMetadata=true, useLocalSessionState=true, maintainTimeStats=false, prepStmtCacheSize=350, prepStmtCacheSqlLimit=2048, password=<masked>}
902 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................."com.mysql.jdbc.Driver"
903 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
904 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
905 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................740000
905 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailFast..........true
906 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
907 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
908 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - jdbc4ConnectionTest.............false
909 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:mysql://localhost/mydb?autoReconnect=true&useSSL=false
909 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........60000
910 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1740000
910 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................200
911 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
912 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
912 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................5
913 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
914 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
918 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
920 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
920 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
921 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutorService........internal
922 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
922 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
922 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
924 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - username........................"myuser"
926 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
931 [http-nio-8080-exec-5] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
1483 [http-nio-8080-exec-5] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@40750294
1486 [http-nio-8080-exec-5] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
1520 [http-nio-8080-exec-5] INFO  org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect

Hibernate persistence.xml configuration:

<property name="hibernate.dialect" value="org.hibernate.dialect.MySQL5Dialect"/>
<property name="hibernate.connection.autocommit" value="false" />

<property name="hibernate.show_sql" value="false" />
<property name="hibernate.format_sql" value="false"/>
<property name="hibernate.connection.provider_class" value="org.hibernate.hikaricp.internal.HikariCPConnectionProvider" />

<property name="hibernate.hikari.dataSource.prepStmtCacheSize" value="350" />
<property name="hibernate.hikari.dataSource.prepStmtCacheSqlLimit" value="2048" />
<property name="hibernate.hikari.dataSource.cachePrepStmts" value="true" />
<property name="hibernate.hikari.dataSource.useServerPrepStmts" value="true" />
<property name="hibernate.hikari.dataSource.useLocalSessionState" value="true" />
<property name="hibernate.hikari.dataSource.useLocalTransactionState" value="true" />
<property name="hibernate.hikari.dataSource.rewriteBatchedStatements" value="true" />
<property name="hibernate.hikari.dataSource.cacheResultSetMetadata" value="true" />
<property name="hibernate.hikari.dataSource.cacheResultSetMetadata" value="true" />
<property name="hibernate.hikari.dataSource.cacheServerConfiguration" value="true" />
<property name="hibernate.hikari.dataSource.elideSetAutoCommits" value="true" />
<property name="hibernate.hikari.dataSource.maintainTimeStats" value="false" />

<!--
    MySQL:  
    interactive_timeout = 7200
    wait_timeout = 1800
    max_connections = 200

    idleTimeout, maxLifetime should be 1min less than wait_timeout = 1740s or 1740000ms
 --> 

<property name="hibernate.hikari.minimumIdle" value="5" />
<property name="hibernate.hikari.maximumPoolSize" value="200" /> 
<property name="hibernate.hikari.idleTimeout" value="740000" /> 
<property name="hibernate.hikari.maxLifetime" value="1740000" /> 
<property name="hibernate.hikari.leakDetectionThreshold" value="60000" /> 

<property name="javax.persistence.jdbc.driver" value="com.mysql.jdbc.Driver" />
<property name="javax.persistence.jdbc.url" value="jdbc:mysql://localhost/mydb?autoReconnect=true&amp;useSSL=false" />
<property name="javax.persistence.jdbc.user" value="myuser" />
<property name="javax.persistence.jdbc.password" value="mypassword" />

HikariCP housekeeper log:

1621219 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=27, active=22, idle=5, waiting=0)
1621220 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup  stats (total=37, active=33, idle=4, waiting=0)

MySQL thrads

Threads_connected:  22
Threads_created:    29
Threads_running:    2

Hikari Leak detection log:

295269 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@64f645d5 on thread http-nio-8080-exec-9, stack trace follows
java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
    at org.hibernate.hikaricp.internal.HikariCPConnectionProvider.getConnection(HikariCPConnectionProvider.java:77)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
    at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:88)
    at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:688)
    at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:75)
    at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2004)
    at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:567)
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:249)
    at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:563)
    at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:132)
    at org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:161)
    at org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:146)
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:249)
    at org.hibernate.collection.internal.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:145)
    at org.hibernate.collection.internal.PersistentBag.size(PersistentBag.java:261)
    at javax.faces.model.ListDataModel.isRowAvailable(ListDataModel.java:110)
    at javax.faces.model.ListDataModel.setRowIndex(ListDataModel.java:185)
    at javax.faces.model.ListDataModel.setWrappedData(ListDataModel.java:220)
    at javax.faces.model.ListDataModel.<init>(ListDataModel.java:79)
    at org.primefaces.component.api.UIData.getDataModel(UIData.java:583)
    at javax.faces.component.UIData.isRowAvailable(UIData.java:343)
    at org.primefaces.component.api.UIData.setRowModel(UIData.java:418)
    at org.primefaces.component.api.UIData.setRowIndex(UIData.java:397)
    at org.primefaces.component.api.UIData.visitTree(UIData.java:629)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at javax.faces.component.UIForm.visitTree(UIForm.java:371)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
    at com.sun.faces.context.PartialViewContextImpl.processComponents(PartialViewContextImpl.java:376)
    at com.sun.faces.context.PartialViewContextImpl.processPartial(PartialViewContextImpl.java:297)
    at javax.faces.context.PartialViewContextWrapper.processPartial(PartialViewContextWrapper.java:183)
    at javax.faces.component.UIViewRoot.encodeChildren(UIViewRoot.java:981)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1779)
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:391)
    at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:125)
    at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:121)
    at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
    at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)

Some code that I use:

Business object layer

@Transactional(readOnly = true)
public List<Person> getPersons() {
    if (persons == null) {
        try {
            persons = new PersonBO().listAll(Person.class);
        } catch (Exception e) {
            getLog().error("Erro", e);
        }
    }
    return persons;
}

DAO Layer

@Transactional(readOnly = true)
public List<E> listAll(Class<E> classEntity) throws Exception {
    return list(createQuery("SELECT o FROM " + classEntity.getSimpleName() + " o"));
}

@Transactional(readOnly = true)
public List<E> list(Query query) throws Exception {
    List<E> entities = null;
    if (query != null) {
        try {
            entities = query.getResultList();
        } catch (Exception e) {
            throw new Exception(e);
        }
    }
    return entities;
}

@Transactional(readOnly = false)
private Query createQuery(String jpql) {
    Query query = null;
    if (jpql != null && !jpql.isEmpty()) {
        query = entityManager.createQuery(jpql);
    }
    return query;
}

brettwooldridge commented 6 years ago

@jnrbo Two things. 200 connections is very high; something is preventing the pool from reaching that size. But that does not seem to be the issue.

Executed rollback on connection com.mysql.jdbc.JDBC4Connection@438b4b42 due to dirty commit state on close().

Regarding the issue, your answer is here. Set org.hibernate.ConnectionReleaseMode to ON_CLOSE.

jnrbo commented 6 years ago

Hi Brett, thank you for answering so fast!

About the pool size, I had to use a pool that big because if not, the error would happen with more frequency. And since the application is already in production, was needed. The application doesn't have more than 4 simultaneously active users.

After adding <property name="hibernate.connection.release_mode" value="ON_CLOSE" />, instead of showing "Executed rollback on connection", Hikari is logging a lot of times:

3731 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@30987dbd

... until fails :

4315 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@668c13ff
8341 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Failed to create/setup connection: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
8343 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Cannot acquire connection from data source
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.Util.getInstance(Util.java:408)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:918)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
    at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2097)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2022)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:779)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.GeneratedConstructorAccessor50.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:389)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:330)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:117)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:123)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:375)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:204)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:459)
    at com.zaxxer.hikari.pool.HikariPool.access$200(HikariPool.java:70)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:696)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:682)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Data source rejected establishment of connection,  message from server: "Too many connections"
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.Util.getInstance(Util.java:408)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:918)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1040)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2191)
    at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2038)
    ... 21 more

34313 [http-nio-8080-exec-3] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Timeout failure stats (total=146, active=146, idle=0, waiting=1)

34315 [http-nio-8080-exec-3] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 08001
34316 [http-nio-8080-exec-3] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - HikariPool-1 - Connection is not available, request timed out after 30008ms.
34316 [http-nio-8080-exec-3] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 08001
34317 [http-nio-8080-exec-3] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Could not create connection to database server. Attempted reconnect 3 times. Giving up.
java.lang.Exception: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

Any tips?

brettwooldridge commented 6 years ago

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Data source rejected establishment of connection, message from server: "Too many connections"

You’re going to have to decrease your pool size. I suggest going back to the default 10 connections.

jnrbo commented 6 years ago

I tried to set:

<property name="hibernate.hikari.minimumIdle" value="3" />
<property name="hibernate.hikari.maximumPoolSize" value="10" />

But the issue continues!

Start log:

747 [http-nio-8080-exec-2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
1126 [http-nio-8080-exec-2] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@19ddd00e
1129 [http-nio-8080-exec-2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
1157 [http-nio-8080-exec-2] INFO  org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
1350 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=1, active=1, idle=0, waiting=0)
1359 [http-nio-8080-exec-2] DEBUG com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Executed rollback on connection com.mysql.jdbc.JDBC4Connection@19ddd00e due to dirty commit state on close().
1367 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup  stats (total=1, active=0, idle=1, waiting=0)
1375 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@1f32c5ff
1380 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@5e0fcfc4
1381 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=3, active=0, idle=3, waiting=0)
2810 [http-nio-8080-exec-2] INFO  org.hibernate.hql.internal.QueryTranslatorFactoryInitiator - HHH000397: Using ASTQueryTranslatorFactory
3103 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@6f1bf106
3118 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@3e20308b
3125 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@16fc7323
3132 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@3a6eea12
3139 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@714f1ca9
3146 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@5aa52b80
3151 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@4ba8a088

And, after a few seconds running (awaiting response) I got:

31382 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=10, active=10, idle=0, waiting=1)
31396 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup  stats (total=10, active=10, idle=0, waiting=1)
32646 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@19ddd00e on thread http-nio-8080-exec-2, stack trace follows
java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
    at org.hibernate.hikaricp.internal.HikariCPConnectionProvider.getConnection(HikariCPConnectionProvider.java:77)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
    at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4069)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1142)
    at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:167)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2762)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2741)
    at org.hibernate.internal.SessionImpl.get(SessionImpl.java:978)
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1033)
    at dao.GenericListDAO.find(GenericListDAO.java:31)
    at bo.SisMenuBO.getMainMenu(SisMenuBO.java:43)
    at mb.SisMainMenuMB.getMainMenu(SisMainMenuMB.java:27)
    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:498)
    at javax.el.BeanELResolver.getValue(BeanELResolver.java:94)
    at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:176)
    at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:203)
    at org.apache.el.parser.AstValue.getValue(AstValue.java:169)
    at org.apache.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:184)
    at com.sun.faces.facelets.el.TagValueExpression.getValue(TagValueExpression.java:109)
    at javax.faces.component.ComponentStateHelper.eval(ComponentStateHelper.java:194)
    at org.primefaces.component.menubar.Menubar.getModel(Menubar.java:86)
    at org.primefaces.component.menu.AbstractMenu.buildMenuFromModel(AbstractMenu.java:36)
    at org.primefaces.component.menu.BaseMenuRenderer.encodeEnd(BaseMenuRenderer.java:35)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:875)
    at org.primefaces.renderkit.CoreRenderer.renderChild(CoreRenderer.java:59)
    at org.primefaces.renderkit.CoreRenderer.renderChildren(CoreRenderer.java:43)
    at org.primefaces.component.layout.LayoutUnitRenderer.encodeEnd(LayoutUnitRenderer.java:51)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:875)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1786)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at javax.faces.render.Renderer.encodeChildren(Renderer.java:168)
    at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:845)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1779)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:402)
    at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:125)
    at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:121)
    at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
    at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    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)

33159 [http-nio-8080-exec-2] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=0)
33161 [http-nio-8080-exec-2] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null
33162 [http-nio-8080-exec-2] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - HikariPool-1 - Connection is not available, request timed out after 30006ms.
java.lang.Exception: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at dao.GenericListDAO.getSingleResult(GenericListDAO.java:93)
    at dao.GenericListDAO.findByFields(GenericListDAO.java:120)
    at bo.BO.findByFields(BO.java:119)
    at bo.SisMenuBO.isPerm(SisMenuBO.java:153)
    at bo.SisMenuBO.getSubmenuItens(SisMenuBO.java:131)
    at bo.SisMenuBO.setItemAsSubmenuUIComponent(SisMenuBO.java:84)
    at bo.SisMenuBO.setItemAsUIComponent(SisMenuBO.java:117)
    at bo.SisMenuBO.getMainMenu(SisMenuBO.java:56)
    at mb.SisMainMenuMB.getMainMenu(SisMainMenuMB.java:27)
    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:498)
    at javax.el.BeanELResolver.getValue(BeanELResolver.java:94)
    at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:176)
    at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:203)
    at org.apache.el.parser.AstValue.getValue(AstValue.java:169)
    at org.apache.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:184)
    at com.sun.faces.facelets.el.TagValueExpression.getValue(TagValueExpression.java:109)
    at javax.faces.component.ComponentStateHelper.eval(ComponentStateHelper.java:194)
    at org.primefaces.component.menubar.Menubar.getModel(Menubar.java:86)
    at org.primefaces.component.menu.AbstractMenu.buildMenuFromModel(AbstractMenu.java:36)
    at org.primefaces.component.menu.BaseMenuRenderer.encodeEnd(BaseMenuRenderer.java:35)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:875)
    at org.primefaces.renderkit.CoreRenderer.renderChild(CoreRenderer.java:59)
    at org.primefaces.renderkit.CoreRenderer.renderChildren(CoreRenderer.java:43)
    at org.primefaces.component.layout.LayoutUnitRenderer.encodeEnd(LayoutUnitRenderer.java:51)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:875)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1786)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at javax.faces.render.Renderer.encodeChildren(Renderer.java:168)
    at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:845)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1779)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1782)
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:402)
    at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:125)
    at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:121)
    at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
    at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    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)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692)
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602)
    at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:560)
    at dao.GenericListDAO.getSingleResult(GenericListDAO.java:88)
    ... 62 more
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1934)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1903)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881)
    at org.hibernate.loader.Loader.doQuery(Loader.java:925)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342)
    at org.hibernate.loader.Loader.doList(Loader.java:2622)
    at org.hibernate.loader.Loader.doList(Loader.java:2605)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434)
    at org.hibernate.loader.Loader.list(Loader.java:2429)
    at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501)
    at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371)
    at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1339)
    at org.hibernate.internal.QueryImpl.list(QueryImpl.java:87)
    at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606)
    at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:529)
    ... 63 more
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30006ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:666)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:182)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
    at org.hibernate.hikaricp.internal.HikariCPConnectionProvider.getConnection(HikariCPConnectionProvider.java:77)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
    ... 84 more

I had look at SisMenuBO and SisMainMenuMB and all the public methods are using @Transactional annotation and use only javax.persistence.Query.getSingleResult() or EntityManager.find().

brettwooldridge commented 6 years ago

@vladmihalcea Can you help out here, I'm in over my head?

vladmihalcea commented 6 years ago

@brettwooldridge @jnrbo There are many issues here.

If you want to use Hikari, you should not provide these properties:

<property name="javax.persistence.jdbc.driver" value="com.mysql.jdbc.Driver" />
<property name="javax.persistence.jdbc.url" value="jdbc:mysql://localhost/mydb?autoReconnect=true&amp;useSSL=false" />
<property name="javax.persistence.jdbc.user" value="myuser" />
<property name="javax.persistence.jdbc.password" value="mypassword" />

Looks like you activated hibernate.enable_lazy_load_no_trans. That's a a bad idea. at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:249)
You don't need to set this property:
```
<property name="hibernate.connection.release_mode" value="ON_CLOSE" />
```
Why did you activate it? The connection should be closed when the transaction is ended, which is how RESOURCE_LOCAL should work. You need to remove this property and use the default mode.
This exception shows that you are running out of connections:
```
Data source rejected establishment of connection,  message from server: "Too many connections"
```
Maybe the pool is set to a higher value than what the database can offer.

This one:

Connection is not available, request timed out after 30004ms.

might indicate some long-running transactions.

Use FlexyPool to get a better understanding of what happens inside your application when it comes to connection management.

jnrbo commented 6 years ago

@brettwooldridge @vladmihalcea, Thank you for answering!

1 - I provide those properties because in HikariCP Github's page is written:

The MySQL DataSource is known to be broken with respect to network timeout support. Use jdbcUrl configuration instead.

Before using this, I was using datasource properties and the issue was also happening. That's why I changed to jdbc (Since I was getting some time out errors, I thought that would fix it).

2 - I didn't activated. But now I explicit defined to false.

3 - Was @brettwooldridge suggestion! haha, Anyway, I had tried without it, and the main difference is shown here.

4 - My database max connections is defined to 200. And even with maxpools defined to 10 or 20 the error keeps happening.

5 - I don't think that is it. My timeouts are defined to higher values and that happens in different situations.. there's not a pattern regarding queries.

I will try to use FlexyPool. Thank you!

vladmihalcea commented 6 years ago

Before using this, I was using datasource properties and the issue was also happening. That's why I changed to JDBC (Since I was getting some time out errors, I thought that would fix it).

Nope. Using a non-CP is not really a fix for your issue.

I didn't activated. But now I explicit defined to false.

Weird how you got that enabled explicitly.

My database max connections is defined to 200. And even with maxpools defined to 10 or 20 the error keeps happening.

200 connections? That's way too much. Unless you have 64 cores, Intel Octane drives, and 128 GB of RAM, I think you should lower the total amount of connections to 2x the number of cores. Use the Universal Scalability Law to tune that.

I don't think that is it. My timeouts are defined to higher values and that happens in different situations.. there's not a pattern regarding queries.

Use this tool to detect connection leaks during testing. You do have integration tests for all your data access code, right?

jnrbo commented 6 years ago

@vladmihalcea, unfortunately I don't have any tests. It's a legacy project, I'm doing some improvements but since when I migrate the project from a local windows server to a cloud linux server, and inserted HikariCP instead of C3P0, those problems start happening.

The default MySQL max connections is 150. I had set to 200 just because the problem I sad before.

For example, today I leaved the software running all day in production. HikariCP's housekeeper logs is:

35168946 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=117, active=112, idle=5, waiting=0)
35168946 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup  stats (total=117, active=112, idle=5, waiting=0)

And MySQL's threads is:

Threads_connected:  6
Threads_created:        131
Threads_running:        1

(5 from idle and 1 is me, connected remotely)

Those 112 active from Hikari, shouldn't they being released? (Since in MySQL there's no extra running/connected threads)

vladmihalcea commented 6 years ago

@jnrbo If you don't have tests, now it's the time to start adding them.

The Threads_connected shows you how many connections the pool uses at any given time.

Now, reading SPR-13269, you might want to upgrade to 4.2.1 or later to get that fixed.

brettwooldridge commented 6 years ago

@jnrbo If HikariCP is showing 117 connections, and MySQL is showing 5, the same as the HikariCP idle count, this is a clear case of a connection leak.

If the application was run all day, and was actively used, then leaking 112 connections is not such a severe leak. A bad leak can exhaust the pool in seconds. However, when the connections hit the top of the pool, the application is effectively dead.

There is nothing to do except enable the leakDetectionThreshold, set to something generous like 1 minute, and find and fix the leaks.

C3p0 does not track resources and will allow you to abandon connections, HikariCP will not.

vladmihalcea commented 6 years ago

@jnrbo As I said before, you need a way to figure out how the connections are leaked, and the easiest way to do it is with integration tests

Use this tool to detect connection leaks during testing.

Trying to figure it out at runtime where you have concurrency is much more difficult to pinpoint the culprit. Most likely, you need to make sure connections are closed properly if you acquire them manually.

If you don't acquire JDBC connections explicitly, then you need to make sure you use the proper combination of Spring, Hibernate, HikariCP, JDBC driver. Maybe there is a conflict between your dependencies which causes an implicit connection leak.

casparom commented 6 years ago

Hello. Did this problem find a solution? I am having a similar problem at the moment myself. I am running integration tests and each test that spins up the spring context starts 9 or 10 connection to my Postgres database but does not close them after the test finishes and the spring context is closed. That means that if i run around 10 integration tests, each of which spins up its own Spring context, then the number of connections adds up to around 100, which is the limit for my database and all following tests fail.

Using Spring, Hikari, Hibernate, Postgres.

Any help would be highly appreciated.

jnrbo commented 6 years ago

Hi @casparom i did not. The way I found to fix this issue was to increase the max pool size and to reboot my server every night..

rjain610 commented 5 years ago

Hi , I am also facing the same issue as that of @casparom , i have set maximum pool size to 10 connections but every time i restart the server , 10 connections keep adding up. I have to manually kill all connection in database when i restart my application.

Also i get "Read timeout " and "Communication link failure" error (the username,password is right and i am able to connection to application) .

Using Spring 4.x, Hibernate 4.x , Hikari 3.1.0 , mysql-connector-java - 6.0.6 and mysql 5.7

vladmihalcea commented 5 years ago

@rjain610 Maybe the SessionFactory is not closed properly when you close the web server so the connection are dangling. You should also set a connection TTL to a reasonable duration: 1 or 2 minutes.

rjain610 commented 5 years ago

@vladmihalcea This is my hibernate config , am i missing anything ? <bean id="dataSourceAdmin" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">

</bean>

<bean id="sessionFactoryAdmin"
    class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
    <property name="dataSource" ref="dataSourceAdmin" />
    <property name="packagesToScan">
        <array>
            <value>com.entity</value>
        </array>

    </property>
    <property name="hibernateProperties">
        <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.MySQL5Dialect</prop>
            <prop key="hibernate.show_sql">true</prop>
            <prop key="hibernate.jdbc.batch_size">50</prop>
            <prop key="hibernate.connection.autocommit">false</prop>
            <prop key="hibernate.connection.zeroDateTimeBehavior">convertToNull</prop>
            <prop key="hibernate.generate_statistics">true</prop>
        </props>
    </property>
</bean>

<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
    <property name="poolName" value="springApiHikariCP" />
    <property name="connectionTestQuery" value="SELECT 1" />
    <property name="dataSourceClassName"
        value="com.mysql.cj.jdbc.MysqlDataSource" />

    <property name="maximumPoolSize" value="5" />
    <property name="leakDetectionThreshold" value="30000" />
    <!-- <property name="maxLifetime" value="180000" /> -->
    <property name="dataSourceProperties">
        <props>
            <prop key="url">${dburl}</prop>
            <prop key="user">${dbusername}</prop>
            <prop key="password">${dbpassword}</prop>
        </props>
    </property>
</bean>

<bean id="txManager"
    class="org.springframework.orm.hibernate4.HibernateTransactionManager">
    <property name="sessionFactory" ref="sessionFactoryAdmin" />
</bean>

vladmihalcea commented 5 years ago

@rjain610 The properties seem fine. Anyway, you need to read the previous messages about using FlexyPool and this tool to see where the connection leak come from.

I noticed you are using Hibernate 4, which used a different connection management mechanism than Hibernate 5. I'm not sure if that's covered as well in Spring. You have to investigate it and see what exactly is causing this connection leak.

You could try upgrading to Hibernate 5.3 and a newer Spring version and see if the issue still replicates. Maybe it was a bug that was fixed. Hibernate 4 is quite old, and a lot of done ever since.

brettwooldridge commented 5 years ago

@rjain610 You can also investigate using:

SET SESSION net_read_timeout = <seconds>;
SET SESSION net_write_timeout = <seconds>;

Documentation here. You can even investigate using a very short wait_timeout, the default is 28800 seconds. These can be set through the connectionInitSql property, with all statements in a single string, semi-colon separated.

Whatever value you set for wait_timeout, I recommend setting the HikariCP maxLifetime property to several seconds less. In general, I would recommend setting wait_timeout to several minutes, at minimum -- maybe somewhere between 2-5 minutes.

The net_xxx_timeout values should probably cover most network interruptions, and should be roughly 3x your longest running transaction time, as a safety margin.

See also my new wiki page on Rapid Recovery.

rjain610 commented 5 years ago

Hi , i think i have found the reason why my connections are stacking up , by looking at the error logs below i see a pattern where connection is added every thirty minutes and due to some communication link failure the newly added connection does not work and thus HikariCP tries to add a new connection immediately , again this happens whenever a communication link failure occurs . Any suggestions ?

2018-12-12 13:05:37 DEBUG HikariPool:709 -call - PHAHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@3225f0f3
2018-12-12 13:09:46 WARN  PoolBase:175 -isConnectionAlive - PHAHikariCP - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@3225f0f3 (Communications link failure

The last packet successfully received from the server was 248,909 milliseconds ago.  The last packet sent successfully to the server was 5,016 milliseconds ago.)
2018-12-12 13:09:46 DEBUG PoolBase:129 -quietlyCloseConnection - PHAHikariCP - Closing connection com.mysql.cj.jdbc.ConnectionImpl@3225f0f3: (connection is dead)
2018-12-12 13:09:46 DEBUG PoolBase:138 -quietlyCloseConnection - PHAHikariCP - Closing connection com.mysql.cj.jdbc.ConnectionImpl@3225f0f3 failed
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 248,909 milliseconds ago.  The last packet sent successfully to the server was 5,016 milliseconds ago.
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:590)
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:57)
    at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1983)
    at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1936)
    at com.mysql.cj.jdbc.StatementImpl.executeInternal(StatementImpl.java:891)
    at com.mysql.cj.jdbc.StatementImpl.execute(StatementImpl.java:795)
    at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:160)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:179)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:155)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
    at org.hibernate.loader.Loader.doQuery(Loader.java:909)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
    at org.hibernate.loader.Loader.doList(Loader.java:2553)
    at org.hibernate.loader.Loader.doList(Loader.java:2539)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
    at org.hibernate.loader.Loader.list(Loader.java:2364)
    at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496)
    at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
    at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
    at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
    at com.mobe.pha.dao.impl.CommonDaoImpl.dynamicTabsLoader(CommonDaoImpl.java:367)
    at com.mobe.pha.dao.impl.CommonDaoImpl.userLogin(CommonDaoImpl.java:186)
    at com.mobe.pha.service.impl.CommonServiceimpl.userLogin(CommonServiceimpl.java:85)
    at com.mobe.pha.controller.CommonController.userlogin(CommonController.java:65)
    at com.mobe.pha.controller.CommonController$$FastClassBySpringCGLIB$$f24258d8.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:711)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
    at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
    at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:52)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
    at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:58)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:644)
    at com.mobe.pha.controller.CommonController$$EnhancerBySpringCGLIB$$20f8823a.userlogin(<generated>)
    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:498)
    at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:749)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:689)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:83)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:938)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:870)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:961)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:863)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:837)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at com.mobe.pha.util.AuthenticationFilter.enableSecurity(AuthenticationFilter.java:109)
    at com.mobe.pha.util.AuthenticationFilter.doFilterInternal(AuthenticationFilter.java:57)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:108)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:154)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.ui.DefaultLoginPageGeneratingFilter.doFilter(DefaultLoginPageGeneratingFilter.java:155)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:199)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:108)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:344)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:261)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:108)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:94)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:616)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:620)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:502)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1132)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:285)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.cj.core.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 248,909 milliseconds ago.  The last packet sent successfully to the server was 5,016 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:54)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:93)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:133)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:149)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.readPacket(MysqlaProtocol.java:527)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.checkErrorPacket(MysqlaProtocol.java:723)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.sendCommand(MysqlaProtocol.java:662)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.sqlQueryDirect(MysqlaProtocol.java:950)
    at com.mysql.cj.mysqla.MysqlaSession.sqlQueryDirect(MysqlaSession.java:431)
    at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1974)
    ... 125 more
Caused by: java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at com.mysql.cj.core.io.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
    at com.mysql.cj.core.io.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
    at com.mysql.cj.core.io.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
    at java.io.FilterInputStream.read(FilterInputStream.java:133)
    at com.mysql.cj.core.io.FullReadInputStream.readFully(FullReadInputStream.java:58)
    at com.mysql.cj.mysqla.io.SimplePacketReader.readHeader(SimplePacketReader.java:60)
    at com.mysql.cj.mysqla.io.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:48)
    at com.mysql.cj.mysqla.io.MultiPacketReader.readHeader(MultiPacketReader.java:51)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.readPacket(MysqlaProtocol.java:521)
    ... 130 more
2018-12-12 13:09:46 DEBUG HikariPool:709 -call - PHAHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@13031ad2

syifeng commented 5 years ago

I just get the same exception when I use the DB query in thread. Did you solve the exception?

brettwooldridge commented 5 years ago

@rjain610 @syifeng You need to set your maxLifetime to a lower value. I also suggest adding a global socket timeout.

KrishnanRoobanraj commented 2 years ago

Hello

ERROR : hikaripool-1 - connection is not available request timed out after 30000ms my Configurations: spring.datasource.hikari.maximum-pool-size=10 spring.datasource.hikari.minimum-idle=10 spring.datasource.hikari.idle-timeout=10000 spring.datasource.hikari.auto-commit=true spring.datasource.hikari.connection-timeout = 20000 spring.datasource.hikari.max-lifetime= 1000

it Happens when i make a heavy load in testing , the scenario is 100 user making a new Registration request to the site at exact same time , the result is around 25 are getting successfully registered and rest of them are getting the above mentioned error

HELP ME OUT ?

brettwooldridge / HikariCP

Thread leak + Unable to acquire JDBC Connection (Hibernate + Hikari + MySQL) #1030

Environment