Hibernate Search won't index my data on Pivotal Web Services

Question

I have a Spring Boot application integrating Hibernate Search to index my JPA entities and everything works fine locally. I have the following component to create the index when the application starts:

@Component
class SearchIndexBuilder implements ApplicationListener<ApplicationReadyEvent>{
    @PersistenceContext
    private EntityManager entityManager

    void onApplicationEvent(ApplicationReadyEvent event) {
        try {
            FullTextEntityManager fullTextEntityManager =
                Search.getFullTextEntityManager(entityManager);
            fullTextEntityManager.createIndexer().startAndWait()
        } catch (InterruptedException e) {
            System.out.println(
                "An error occurred trying to build the search index: " +
                        e.toString());
        }
    }
}

But when I deploy my application to Pivotal Web Services, the MassIndexer fails with the following exception:

2016-03-21T14:33:33.91+0100 [APP/0]      OUT org.hibernate.exception.GenericJDBCException: Could not open connection
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.IdentifierConsumerDocumentProducer.run(IdentifierConsumerDocumentProducer.java:116) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.OptionallyWrapInJTATransaction.runWithErrorHandler(OptionallyWrapInJTATransaction.java:111) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.ErrorHandledRunnable.run(ErrorHandledRunnable.java:49) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [Hibernate Search: entityloader-6] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:4; busy:4; idle:0; lastwait:30000].
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:681) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:185) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    ... 9 common frames omitted
2016-03-21T14:33:33.91+0100 [APP/0]      OUT 2016-03-21 13:33:33.913 ERROR 16 --- [ entityloader-2] o.h.s.exception.impl.LogErrorHandler     : HSEARCH000058: HSEARCH000116: Unexpected error during MassIndexer operation
2016-03-21T14:33:33.91+0100 [APP/0]      OUT org.hibernate.exception.GenericJDBCException: Could not open connection
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.IdentifierConsumerDocumentProducer.run(IdentifierConsumerDocumentProducer.java:116) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.OptionallyWrapInJTATransaction.runWithErrorHandler(OptionallyWrapInJTATransaction.java:111) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.ErrorHandledRunnable.run(ErrorHandledRunnable.java:49) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_73-]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [Hibernate Search: entityloader-2] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:4; busy:4; idle:0; lastwait:30000].
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:681) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:185) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.91+0100 [APP/0]      OUT    ... 9 common frames omitted
2016-03-21T14:33:33.92+0100 [APP/0]      OUT 2016-03-21 13:33:33.921  WARN 16 --- [ntifierloader-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2016-03-21T14:33:33.92+0100 [APP/0]      OUT 2016-03-21 13:33:33.922 ERROR 16 --- [ntifierloader-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : [Hibernate Search: identifierloader-1] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:4; busy:4; idle:0; lastwait:30000].
2016-03-21T14:33:33.92+0100 [APP/0]      OUT 2016-03-21 13:33:33.922 ERROR 16 --- [ntifierloader-1] o.h.s.exception.impl.LogErrorHandler     : HSEARCH000058: HSEARCH000116: Unexpected error during MassIndexer operation
2016-03-21T14:33:33.92+0100 [APP/0]      OUT org.hibernate.exception.GenericJDBCException: Could not open connection
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.IdentifierProducer.inTransactionWrapper(IdentifierProducer.java:110) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.IdentifierProducer.run(IdentifierProducer.java:95) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.OptionallyWrapInJTATransaction.runWithErrorHandler(OptionallyWrapInJTATransaction.java:114) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.search.batchindexing.impl.ErrorHandledRunnable.run(ErrorHandledRunnable.java:49) ~[hibernate-search-orm-4.5.3.Final.jar!/:4.5.3.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_73-]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_73-]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_73-]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [Hibernate Search: identifierloader-1] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:4; busy:4; idle:0; lastwait:30000].
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:681) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:185) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127) ~[tomcat-jdbc-8.0.30.jar!/:na]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.11.Final.jar!/:4.3.11.Final]
2016-03-21T14:33:33.92+0100 [APP/0]      OUT    ... 10 common frames omitted
2016-03-21T14:33:33.93+0100 [APP/0]      OUT 2016-03-21 13:33:33.933  INFO 16 --- [           main] o.h.s.i.SimpleIndexingProgressMonitor    : HSEARCH000028: Reindexed 0 entities

I've tried to upgrade my ClearDB plan from Spark to Boost, which increased the maximum number of connections on the DB from 4 to 15, but it didn't change anything.

Any idea of what I'm missing?

You can try putting "org.hibernate.jdbc.ConnectionManager" to debug in your environment and track the connection opening and closing statements. — Shailendra, Mar 20 '16 at 18:06
Could you try indexing only one type, rather than have it index all types in parallel (which is the default) ? That should consume less connections. — Sanne, Mar 21 '16 at 02:55
Why are you listening on _any_ application event? That seems wrong to me. I'd replace that code with `@EventListener(ApplicationReadyEvent.class) index() { ... }`. Where are you storing your indexes exactly? It would also be nice to have a bit more stacktrace to figure out when this happens. — Stephane Nicoll, Mar 21 '16 at 09:36
So I modified my SearchIndexBuilder to extend ApplicationListener instead. But I still get the exception after my application has started. I have updated my question with the full stack trace. — Sebastien, Mar 21 '16 at 13:35
By the way, I just tried to disable this event listener and trigger the reindex on a controller request instead, and I'm getting the exact same exception. So it seems to have something to do with the number of DB connections the MassIndexer needs versus what Tomcat on PWS can give me. — Sebastien, Mar 21 '16 at 13:51
I don't know about that thing but yes, the exception tells you that all 4 connections are taken (`[size:4; busy:4; idle:0; lastwait:30000].`). You said you upgraded to 15 but I can see the max size is still 4. I don't understand why it needs 4 connections but that's something Hibernate Search specific I guess. Maybe you should [tune the indexer](https://docs.jboss.org/hibernate/search/3.2/reference/en/html/manual-index-changes.html#search-batchindex-massindexer) to reduce the number of parallel threads? — Stephane Nicoll, Mar 21 '16 at 16:07

Hibernate Search won't index my data on Pivotal Web Services

0 Answers0