[2.4-java] SqlExceptionHelper - Timeout after 120000ms of waiting for a connection

[Johan Dahlberg]

I keep getting this error after upgrading to Play 2.4.x. Is it anything in the JPA implementation that could have caused this error?

2015-07-27 11:51:16,393 - [warn] o.h.e.j.s.SqlExceptionHelper - SQL Error: 0, SQLState: null

2015-07-27 11:51:16,393 - [error] o.h.e.j.s.SqlExceptionHelper - Timeout after 120000ms of waiting for a connection.

2015-07-27 11:51:16,411 - [error] application - 

! @6n0op4afp - Internal server error, for (GET) [/] ->

 

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[QueryTimeoutException: Could not open connection]]

at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.2.jar:2.4.2]

at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.2.jar:2.4.2]

at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.2.jar:2.4.2]

at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.2.jar:2.4.2]

at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.2.jar:2.4.2]

Caused by: javax.persistence.QueryTimeoutException: Could not open connection

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1725) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:458) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getResultList(CriteriaQueryTypeQueryAdapter.java:67) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at dao.AbstractDAO.findMany(AbstractDAO.java:92) ~[classes/:na]

Caused by: org.hibernate.QueryTimeoutException: Could not open connection

at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:83) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

Caused by: java.sql.SQLTimeoutException: Timeout after 120000ms of waiting for a connection.

at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:227) ~[HikariCP-2.3.7.jar:na]

at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182) ~[HikariCP-2.3.7.jar:na]

at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93) ~[HikariCP-2.3.7.jar:na]

at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

application.conf:

db {

  default {

    driver=com.mysql.jdbc.Driver

    url="jdbc:mysql://localhost/maw?tinyInt1isBit=false"

    username="root"

    password="secret"

    jndiName=DefaultDS

    hikaricp {

      connectionTimeout=2 minutes

    }

    initializationFailFast=false

    connectionTestStatement="SELECT 1"

    idleMaxAge=10 minutes

    idleConnectionTestPeriod=30 seconds

    logStatements=true

    maxConnectionAge=1 hour

  }

}

ebeanEnabled = false

jpa.default=defaultPersistenceUnit

persistence.xml:

<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"

             xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

             xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd"

             version="2.1">

    <persistence-unit name="defaultPersistenceUnit" transaction-type="RESOURCE_LOCAL">

        <provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>

        <non-jta-data-source>DefaultDS</non-jta-data-source>

        <properties>

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

            <property name="hibernate.enable_lazy_load_no_trans" value="true" />

            <property name="hibernate.format_sql" value="true" />

            <property name="hibernate.hbm2ddl.auto" value="validate"/>

            <property name="hibernate.max_fetch_depth" value="5" />

            <property name="hibernate.show_sql" value="false" />

        </properties>

    </persistence-unit>

</persistence>

[Johan Dahlberg]

I forgot to add the the MySQL server is up and I can access it through MySQL Workbench and an older version of the application with the same configuration. So it feels like something has changed since 2.3.x.

/Johan

[p...@semlab.nl]

connectionTestStatement

Only works with BoneCP. For HikariCP, use 

hikaricp.connectionTestQuery

Op maandag 27 juli 2015 16:09:36 UTC+2 schreef Johan Dahlberg:

[Johan Dahlberg]

Thanks!

But the error is still occurring.

/Johan

[sachin walia]

You should post to https://groups.google.com/forum/#!forum/hikari-cp.

Author of HikariCP - Brett Wooldridge responds promptly. He'll be able to tell you what is happening. Play plugin is just a shell over HikariCP.

[Johan Dahlberg]

Thanks!

The reason for the error if anyone else has this problem is that the maximumPoolSize by default is 10 connections. This is configured with db.default.hikaricp.maximumPoolSize and bonecp has a default value that is higher than that.

/Johan

[Johan Dahlberg]

The leak detection is triggered in HikariCP so something is causing a leak. Anyone that has seen problems with leaks in JPA/Hibernate in Play before?

2015-07-30 15:53:15,421 - [warn] c.z.h.p.LeakTask - Connection leak detection triggered for connection com.mysql.jdbc.JDBC4Connection@53b6a428, stack trace follows

java.lang.Exception: Apparent connection leak detected

at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

/Johan

[Johan Dahlberg]

Forgot to write that no connection looks to be closed.

/Johan

[Johan Dahlberg]

I think one connection is created for every DAO that I inject. They look like this, what do I do wrong since none is closed?

UserDAO:

public class UserDAO extends AbstractDAO<User, User_> {
    JedisPool jedisPool;

    @Inject
    public UserDAO(final JPAApi jpaApi, JedisPool jedisPool) {
        super(jpaApi, User.class, User_.class);
        this.jedisPool = jedisPool;
    }

    ...
}

AbstractDAO:

public abstract class AbstractDAO<T extends AbstractModel, M extends AbstractModel_> {
    protected final Class<T> classType;
    protected final EntityManager em;
    protected final CriteriaBuilder cb;

    public AbstractDAO(final JPAApi jpaApi, Class<T> classType, Class<M> metaType) {
        this.em = jpaApi.em("default");
        this.cb = em.getCriteriaBuilder();
        this.classType = classType;
    }

    ...
}

/Johan

[Mitesh Sharma]

Hey Johan,

I am also seeing same issue on my local play 2.4.2 setup. Did you get fix for this issue?