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 · 18 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/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

@dmatej
Copy link

dmatej commented Dec 1, 2024

One idea about those locks - when the class is not final and somebody extends it and overrides a method and makes it synchronized, the locking breaks. So when you introduce these locks, these classes must be final OR have to provide access to the lock - and it is still a breaking change which should not be in 4.0.4.

However I am not sure if this is the case, I just know that GlassFish 7.0.20-SNAPSHOT randomly doesn't pass the TCK tests with this error:

Error allocating connection: [Failed to obtain/create connection from connection pool [__TimerPool]. Reason: No available resources and wait time 60000 ms expired.]

@cserepj
Copy link

cserepj commented Dec 6, 2024

Seeing probably the same stuff, downgrading indeed helps, have a thread dump from the deadlock condition:

ESC[36mjetty-society_1 |ESC[0m "qtp1860944798-460" ESC[36mjetty-society_1 |ESC[0m java.lang.Thread.State: WAITING ESC[36mjetty-society_1 |ESC[0m at [email protected]/jdk.internal.misc.Unsafe.park(Native Method) ESC[36mjetty-society_1 |ESC[0m at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221) ESC[36mjetty-society_1 |ESC[0m at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754) ESC[36mjetty-society_1 |ESC[0m at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990) ESC[36mjetty-society_1 |ESC[0m at [email protected]/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:154) ESC[36mjetty-society_1 |ESC[0m at [email protected]/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:323) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:323) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:624) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:611) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectOneRow(DatasourceCallQueryMechanism.java:813) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectOneRowFromTable(ExpressionQueryMechanism.java:2912) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectOneRow(ExpressionQueryMechanism.java:2865) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.ReadObjectQuery.executeObjectLevelReadQuery(ReadObjectQuery.java:563) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1236) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:913) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1195) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.ReadObjectQuery.execute(ReadObjectQuery.java:448) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1283) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:3028) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1841) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1823) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1773) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.jpa.EntityManagerImpl.executeQuery(EntityManagerImpl.java:999) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.jpa.EntityManagerImpl.findInternal(EntityManagerImpl.java:941) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:817) ESC[36mjetty-society_1 |ESC[0m at org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:691)

@rfelcman
Copy link
Contributor

rfelcman commented Dec 11, 2024

I'm continue to check and understand this issue, but what sounds me strange is. How two/multiple threads should "fight" for
same instance lock/unlock of the org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor#instanceLock?

On the begining from Jakarta Persistence Specification 3.1
https://jakarta.ee/specifications/persistence/3.1/jakarta-persistence-spec-3.1#obtaining-an-entitymanager
7.2. Obtaining an EntityManager
...
An entity manager must not be shared among multiple concurrently executing threads, as the entity manager and persistence context are not required to be threadsafe. Entity managers must only be accessed in a single-threaded manner.
...

and let's look to EclipseLink (little bit simplified) what is behind instance of jakarta.persistence.EntityManager from the context of DB connection
org.eclipse.persistence.internal.jpa.EntityManagerImpl
org.eclipse.persistence.internal.sessions.UnitOfWorkImpl
org.eclipse.persistence.sessions.server.ServerSession
org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor
org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor include instance of instanceLock
java.sql.Connection

All calls of the class instances are expected to call in single thread way, but I don't understand how is possible, that in this case org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor#instanceLock instance is accessed by two threads .
There should be two instances of org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.
Is it really jakarta.persistence.EntityManager instance called in one thread and not shared across multiple threads?
This is why test case for me important. There should be something hidden in SpringBoot.

Just for example there is something what I produced, but it seems, that SpringBoot correctly creates two instances of the test.org.eclipse.persistence.testing.models.jpa.springboot.PersonRepository

package test.org.eclipse.persistence.testing.models.jpa.springboot;

import org.springframework.data.jpa.repository.JpaRepository;
import org.springframework.stereotype.Repository;

import java.util.List;

@Repository
public interface PersonRepository extends JpaRepository<Person, Integer> {

    Person findPersonById(Integer id);

    List<Person> queryAllByIdGreaterThan(Integer idIsGreaterThan);
}
@ContextConfiguration(classes = { PersonApplication.class, EclipseLinkJpaConfiguration.class })
@DataJpaTest
@AutoConfigureTestDatabase(replace = AutoConfigureTestDatabase.Replace.NONE)
public class TestPersonRepository {

    private final int NO_PERSONS = 10;

    @Autowired
    private PersonRepository personRepository;

    @Autowired
    private HikariDataSource dataSource;

    @Test
    public void testPerson() throws SQLException {
        Thread thread1 = new Thread(() -> {
            List<Person> persons = personRepository.queryAllByIdGreaterThan(0);
            assertTrue(persons.size() > 1);

        });
        Thread thread2 = new Thread(() -> {
            List<Person> persons = personRepository.queryAllByIdGreaterThan(0);
            assertTrue(persons.size() > 1);

        });
        thread1.start();
        thread2.start();
        HikariDataSourcePoolMetadata hikariDataSourcePoolMetadata =new HikariDataSourcePoolMetadata(dataSource);
        System.out.println("#################################" + hikariDataSourcePoolMetadata.getActive());
    }

So lifecycle of the something like

 @Autowired
    private PersonRepository personRepository;

is important. Mainly if this kind of the variable is not shared across threads.
I know, that code with synchronized was "errorless", but maybe new ReentrantLock style uncovered some issue at the outer level.
Of course there still should but in the EclipseLink code and test case which leads into mentioned error will help to solve this issue. Stack/thread traces are fine, but in cases like this are additionally important conditions/code calls which leads into deadlock.

@rfelcman
Copy link
Contributor

There is my current test case which doesn't lead into issue yet. Lets say it's some starting point. Feel free to take a look and modify it include application properties to simulate your environment.
This one is based on Apache Derby DB which must be started in project by mvn derby:run.
jpa-bug-2219-SpringbootHikariDSDeadLock.tar.gz

@dubrouski
Copy link

dubrouski commented Dec 12, 2024

I'm continue to check and understand this issue, but what sounds me strange is. How two/multiple threads should "fight" for same instance lock/unlock of the org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor#instanceLock?
...
All calls of the class instances are expected to call in single thread way, but I don't understand how is possible, that in this case org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor#instanceLock instance is accessed by two threads . There should be two instances of org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor. Is it really jakarta.persistence.EntityManager instance called in one thread and not shared across multiple threads? This is why test case for me important. There should be something hidden in SpringBoot.

The issue might lay in the way DatasourceAccessor instances are obtained through the clone(). The copy is shallow, thus the recreated lock is the same instance as the one used in the original DatasourceAccessor instance. Resetting instanceLock to the newly created ReentrantLock seems to solve the issue.

Quick fix with the diagnostic logging:

    /**
     * Clone the accessor.
     */
    @Override
    public Object clone() {
        try {
            DatasourceAccessor accessor = (DatasourceAccessor)super.clone();
            
            // reset the instanceLock, otherwise the lock will be shared across multiple instances
            accessor.instanceLock = new MyReentrantLock();
            
            if(accessor.customizer != null) {
                accessor.customizer.setAccessor(accessor);
            }

            LOG.debug(
                "Cloned {} to {}. Clone's lock owner: {}. Lock ids: {} vs {}.",
                this.hashCode(), accessor.hashCode(), accessor.instanceLock.getOwner(),
                this.instanceLock.hashCode(), accessor.instanceLock.hashCode()
            );

            return accessor;
        } catch (CloneNotSupportedException exception) {
            throw new InternalError("clone not supported");
        }
    }

@jeevangali-agi
Copy link

jeevangali-agi commented Dec 16, 2024

are we releasing a new version with 4.05? This seems to be affecting everywhere!

@rfelcman
Copy link
Contributor

are we releasing a new version with 4.05? This seems to be affecting everywhere!

It depends on #2328 and #2329

@rfelcman
Copy link
Contributor

rfelcman commented Dec 19, 2024

First release candidate of EclipseLink 4.0.5 (4.0.5-RC1) is available.
You can download it from usual sources like:
Maven Central
Milestone builds: https://download.eclipse.org/rt/eclipselink/milestones/4.0.5/RC1/
List of changes against 4.0.4 is available at: https://github.com/eclipse-ee4j/eclipselink/releases/tag/4.0.5-RC1

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

10 participants