Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Getting "Could not open JPA EntityManager" because of "Connection is not available, request timed out after 30000ms" with HikariCP Datasource in Spring #2219

Open
funfried opened this issue Jul 24, 2024 · 10 comments

Comments

@funfried
Copy link

Describe the bug
Recently I updated to EclipseLink 4.0.4 since then I get this error while booting my Spring Boot 3.3.2 app:

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms (total=30, active=30, idle=0, waiting=0)
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:686)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:179)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:127)
	at org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:140)
	at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:174)
	at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.connectInternal(DatasourceAccessor.java:374)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.connectInternal(DatabaseAccessor.java:318)
	at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.reconnect(DatasourceAccessor.java:617)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.reconnect(DatabaseAccessor.java:1820)
	at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:345)
	at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.beginTransaction(DatasourceAccessor.java:269)
	at org.eclipse.persistence.sessions.server.ClientSession.retryTransaction(ClientSession.java:788)
	at org.eclipse.persistence.internal.sessions.AbstractSession.basicBeginTransaction(AbstractSession.java:751)
	at org.eclipse.persistence.sessions.server.ClientSession.addWriteConnection(ClientSession.java:757)
	at org.eclipse.persistence.sessions.server.ServerSession.acquireClientConnection(ServerSession.java:271)
	at org.eclipse.persistence.sessions.server.ClientSession.getAccessor(ClientSession.java:391)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.getAccessor(UnitOfWorkImpl.java:1960)
	at org.eclipse.persistence.internal.jpa.EntityManagerImpl.unwrap(EntityManagerImpl.java:2906)
	at java.base\/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base\/java.lang.reflect.Method.invoke(Method.java:580)
	at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:364)
	at jdk.proxy2\/jdk.proxy2.$Proxy146.unwrap(Unknown Source)
	at org.springframework.orm.jpa.vendor.EclipseLinkJpaDialect.beginTransaction(EclipseLinkJpaDialect.java:131)
	at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:420)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:532)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:405)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:604)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:373)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:768)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:720)

I have no idea where this could come from, I just know as soon as I downgrade to EclipseLink 4.0.2 (didn't test with 4.0.3 as I can only reproduce this error on my production environment, it's not happening on my local machine nor on our testing environment).

It seems the EntityManager cannot get a database connection before a timeout kicks in. My HikariCP database connection pool has no special configurations except that I set the MaximumPoolSize to 30, everything else (besides the DB connection settings) are default values.

As mentioned before, it works on my local machine and in our testing environment, the only difference I can think of is the load on the service. As soon as the service starts up in production, it will be called by around 2k IoT devices which is not the case on my local machine and on testing, everything else is pretty much the same. I did not change anything but the EclipseLink version from 4.0.4 to 4.0.2 and the error was gone and everything worked perfectly well again.

To Reproduce
Steps/resources to reproduce the behavior:
I have no idea how this could be reproduced, I just thought you should know about the issue, I'll might be able to come up with a test application.

  • EclipseLink version: 4.0.4
  • Java/JDK version: Azul JDK 21
  • JDBC driver provider/version: Latest PostgreSQL JDBC driver (42.7.3)
  • Spring Boot version: 3.3.2
  • Spring FW version: 6.1.11

Cheers,
Fabian

@funfried
Copy link
Author

FYI: I just tried EclipseLink 4.0.3 and this version works also great for me, so the bug must have been introduced in 4.0.4

@fwiesweg
Copy link

I'm having a similar issue around locking after the upgrade from 4.0.3 to 4.0.4. Unfortunately, I went with DBCP's default no-timeout behaviour, causing my entire fleet of servers to deadlock every few minutes to hours.

My guess is that it is caused by #2181 -- this pull request replaces the synchronized methods incrementCallCount and decrementCallCount in DatasourceAccessor by a ReentrantLock.

The issue seems to be that the new ReentrantLock instanceLock at 3cadbb11 in that class is held by one thread, which is waiting for a new connection from my connection pool. Unfortunately, this pool has been exhausted at the moment the stack has been recorded, as evident from waiting in LinkedBlockingDeque.takeFirst (it's waiting for caec1e6), so this thread is starved. At the same time, I have a bunch of other threads waiting for that exact instanceLock at 3cadbb11 to be released in order to make progress and finally return their connection object to the connection pool.

I seriously wonder as to why this is triggered now, the locking schema looks exactly the same. I guess we got lucky before because of some minor semantic difference between synchronized and ReentrantLock? I feel it should have been possible to starve before as well, it just never happened.

Starved thread:

        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        - parking to wait for <caec1e6> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
        at [email protected]/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3465)
        at [email protected]/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3436)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1625)
        at app//org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:1324)
        at app//org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:313)
        at app//org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:233)
        at app//de.isatech.water.regenwolke.persistence.eclipselink.DbcpDataSource$ConnectionObjectPool.borrowObject(DbcpDataSource.java:72)
        at app//de.isatech.water.regenwolke.persistence.eclipselink.DbcpDataSource$ConnectionObjectPool.borrowObject(DbcpDataSource.java:56)
        at app//org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:139)
        at app//org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:140)
        at app//org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:174)
        at app//org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.connectInternal(DatasourceAccessor.java:374)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.connectInternal(DatabaseAccessor.java:318)
        at app//org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.reconnect(DatasourceAccessor.java:617)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.reconnect(DatabaseAccessor.java:1820)
        at app//org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:345)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:624)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569)
        at app//org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048)
        at app//org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:611)
        at app//org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:263)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:352)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:792)
        at app//org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2848)
        at app//org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2801)
        at app//org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:584)

   Locked ownable synchronizers:
        - locked <3cadbb11> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

Multiple threads trying to return the connection objects (just an example here):

        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        - waiting to lock <3cadbb11> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) 
        at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:938)
        at [email protected]/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
        at [email protected]/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
        at app//org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.decrementCallCount(DatasourceAccessor.java:298)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeStatement(DatabaseAccessor.java:422)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.releaseStatement(DatabaseAccessor.java:1860)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:723)
        at app//org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569)
        at app//org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048)
        at app//org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:611)
        at app//org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:263)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:352)
        at app//org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:792)
        at app//org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2848)
        at app//org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2801)
        at app//org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:584)

   Locked ownable synchronizers:
        - ... ( a series of unrelated locks)

@avgustinmm
Copy link

Hi,
we experienced the same issue with 4.0.4 and the downgrade to 4.0.3 seemed to fix the issue.
Into the changes introduced into 4.0.4 I see:
image
which seems a little bit strange - could that be related to the bug?

avgustinmm added a commit to bosch-io/hawkbit that referenced this issue Aug 8, 2024
avgustinmm added a commit to bosch-io/hawkbit that referenced this issue Aug 8, 2024
avgustinmm added a commit to eclipse/hawkbit that referenced this issue Aug 8, 2024
@rfelcman
Copy link
Contributor

rfelcman commented Aug 9, 2024

Hello,
this change #2228 was due issue issue #1970 , but into 4.x branch was merged yesterday (08-AUG-2024). It's not part of already released 4.0.4 . Master branch is 5.x line.

@rfelcman
Copy link
Contributor

rfelcman commented Aug 9, 2024

@chschu
Copy link

chschu commented Sep 9, 2024

@fwiesweg: I'm encountering the exact same deadlocks during load tests. Replacing synchronized with ReentrantLock might have introduced subtle changes. DatabaseAccessor has some synchronized methods that used to lock the same monitor as the no longer synchronized methods of DatasourceAccessor.

Downgrading to 4.0.3 for now.

@SAPJens
Copy link

SAPJens commented Sep 11, 2024

@rfelcman This issue seems to be introduced with #2181
The following happens:
Scenario:
Springboot app with Hikari as database pool.
Prerequisite: Enough requests to get the DB pool full.

Now the following seems to happen:
Thread 1 tries to get a connection, but the pool is full and the thread needs to wait.
However, this thread has set a lock through DatasourceAccessor.
Thread 2 already has a connection and wants to close it.
This does not work as DatasourceAccessor is locked by thread 1.
This now means, that no old connections can be released anymore and thus the system is in a deadlock.

Stacktraces:
Thread 1

"Thread 1" - Thread t@10272
   java.lang.Thread.State: TIMED_WAITING
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        - parking to wait for <3643bb91> (a java.util.concurrent.SynchronousQueue$TransferQueue)
        at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
        at [email protected]/java.util.concurrent.SynchronousQueue$TransferQueue.transfer(SynchronousQueue.java:704)
        at [email protected]/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:903)
        at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:151)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:127)
        at org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:140)
        at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:174)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.connectInternal(DatasourceAccessor.java:374)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.connectInternal(DatabaseAccessor.java:318)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.reconnect(DatasourceAccessor.java:617)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.reconnect(DatabaseAccessor.java:1820)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:345)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:624)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569)
        at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048)
        at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:611)
        at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:263)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:352)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:792)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2848)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2801)
        at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:584)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1236)
        at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:913)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1195)
        at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:485)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1283)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:3028)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1841)
        at org.eclipse.persistence.internal.sessions.AbstractSession.retryQuery(AbstractSession.java:1912)
        at org.eclipse.persistence.sessions.server.ClientSession.retryQuery(ClientSession.java:704)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.retryQuery(UnitOfWorkImpl.java:5828)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1878)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1823)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1788)
        at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:263)
        at org.eclipse.persistence.internal.jpa.QueryImpl.getSingleResult(QueryImpl.java:531)
        at org.eclipse.persistence.internal.jpa.EJBQueryImpl.getSingleResult(EJBQueryImpl.java:400)
        at jdk.internal.reflect.GeneratedMethodAccessor88.invoke(Unknown Source)
        at [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at [email protected]/java.lang.reflect.Method.invoke(Method.java:569)
        at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:418)
        at jdk.proxy3/jdk.proxy3.$Proxy206.getSingleResult(Unknown Source)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:223)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:92)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:152)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:140)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryQueryMethodInvoker$$Lambda$1645/0x0000000800ea7800.invoke(Unknown Source)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:170)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:158)
        at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164)
        at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:70)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.transaction.interceptor.TransactionInterceptor$$Lambda$1644/0x0000000800ea71c0.proceedWithInvocation(Unknown Source)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:379)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:138)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:136)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:223)
        at jdk.proxy3/jdk.proxy3.$Proxy204.findOneByTenantId(Unknown Source)

Thread 2

"Thread 2" - Thread t@4530
   java.lang.Thread.State: WAITING
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        - waiting to lock <4c14ce1b> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) owned by "http-nio-8080-exec-52" t@10272
        at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:938)
        at [email protected]/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
        at [email protected]/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.decrementCallCount(DatasourceAccessor.java:298)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeStatement(DatabaseAccessor.java:422)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.releaseStatement(DatabaseAccessor.java:1860)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:723)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569)
        at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048)
        at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:611)
        at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:263)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:352)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:792)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2848)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2801)
        at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:584)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1236)
        at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:913)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1195)
        at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:485)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1283)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:3028)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1841)
        at org.eclipse.persistence.internal.sessions.AbstractSession.retryQuery(AbstractSession.java:1912)
        at org.eclipse.persistence.sessions.server.ClientSession.retryQuery(ClientSession.java:704)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.retryQuery(UnitOfWorkImpl.java:5828)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1878)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1823)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1788)
        at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:263)
        at org.eclipse.persistence.internal.jpa.QueryImpl.getSingleResult(QueryImpl.java:531)
        at org.eclipse.persistence.internal.jpa.EJBQueryImpl.getSingleResult(EJBQueryImpl.java:400)
        at jdk.internal.reflect.GeneratedMethodAccessor88.invoke(Unknown Source)
        at [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at [email protected]/java.lang.reflect.Method.invoke(Method.java:569)
        at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:418)
        at jdk.proxy3/jdk.proxy3.$Proxy206.getSingleResult(Unknown Source)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:223)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:92)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:152)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:140)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryQueryMethodInvoker$$Lambda$1645/0x0000000800ea7800.invoke(Unknown Source)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:170)
        at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:158)
        at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164)
        at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:70)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.transaction.interceptor.TransactionInterceptor$$Lambda$1644/0x0000000800ea71c0.proceedWithInvocation(Unknown Source)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:379)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:138)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:136)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:223)
        at jdk.proxy3/jdk.proxy3.$Proxy185.findOneByKey(Unknown Source)

@rfelcman
Copy link
Contributor

Could You please provide complete stack trace, or at least into EntityManager calls. Described case above looks like, that same instance of the EntityManager is shared across multiple threads which is wrong pattern.

@SAPJens
Copy link

SAPJens commented Sep 13, 2024

Could You please provide complete stack trace, or at least into EntityManager calls. Described case above looks like, that same instance of the EntityManager is shared across multiple threads which is wrong pattern.

@rfelcman I have updated my original comment with the extended stacktrace:
#2219 (comment)

rfelcman added a commit to rfelcman/eclipselink that referenced this issue Sep 18, 2024
…of "Connection is not available, request timed out after 30000ms" with HikariCP Datasource in Spring eclipse-ee4j#2219

Signed-off-by: Radek Felcman <[email protected]>
@rfelcman
Copy link
Contributor

Hello, in the attachment You can find initial test project which is passing now (simple test with one thread).
It's based on Apache Derby (in-memory mode) which is automatically started during Maven lifecycle mvn clean verify.
Test is in org.eclipse.persistence.testing.tests.jpa.springboot.TestPersonRepository#testPerson and Derby should be started by mvn derby:run if test is called from IDE.
As I don't have experience with Springboot, I'd like ask You check and extend this test case to simulate mentioned bug. E.g. it's not clear how is @Repository class/interface designed. Just interface or interface plus some implementation class. Another question leads into application.properties and Hikari DataSource related properties which are specified in Your project.
jpa-bug-2219-SpringbootHikariDSDeadLock.tar.gz

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants