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

Race condition EBean 14 #3412

Closed
tbee opened this issue May 31, 2024 · 7 comments · Fixed by #3415
Closed

Race condition EBean 14 #3412

tbee opened this issue May 31, 2024 · 7 comments · Fixed by #3415
Assignees
Labels
Milestone

Comments

@tbee
Copy link
Contributor

tbee commented May 31, 2024

We've just reverted back to EBean 12 from Ebean 14.3.0. We observe the following behavior:

A request comes in and EBean claims a connection from the pool. A few milliseconds later a second connection is requested. Normally both are released afterwards. Peachy.

However, if the load is high, the whole pool is drained by requests claiming their first connection, the remaining requests are waiting on the pool's semaphore. Then the requests that got their first connection attempt to get a second, and then also wait on the pool's semaphore. All threads are now blocked, with the only escape being the timeout.

I've got a cleaned log for one thread below:

08:38:40,704 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] getConnection
08:38:40,718 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] Got connectionn 29fa10a2
08:38:40,725 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] returnConnection(29fa10a2, false)
08:38:40,800 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] getConnection
08:38:40,800 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] Got connection 31be82a7
08:38:40,830 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] getConnection
08:39:10,839 TRACE (default task-14) [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] returnConnection(31be82a7, false)
08:39:10,842 ERROR (default task-14) [io.undertow.request] UT005023: Exception handling request to /api/users/by_uuid/883b5486-43d8-4a23-8411-512b22082d75: org.jboss.resteasy.spi.UnhandledException: javax.persistence.PersistenceException: java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/HealthcareDS

You see a first correct get/return connection. The second get is also successful, but before returning that connection a third get (30 ms later) is attempted. The pool is exhausted at that time.

What has changed in EBean 14 that it requires two connections?

I'l continue my investigation.

@tbee
Copy link
Contributor Author

tbee commented May 31, 2024

It appears the second connection is for a ImplicitReadOnlyTransaction which has its own connection.

First connection is used:

logSql:405, CQueryEngine (io.ebeaninternal.server.query)
findMany:348, CQueryEngine (io.ebeaninternal.server.query)
findMany:126, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findList:403, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1430, DefaultServer (io.ebeaninternal.server.core)
findOne:1060, DefaultServer (io.ebeaninternal.server.core)
findOne:1569, DefaultOrmQuery (io.ebeaninternal.server.querydefn)
findOne:429, DefaultExpressionList (io.ebeaninternal.server.expression)
byUUID:54, UserFinder (com.nedap.healthcare.administration.authorization.finder)
...

Second connection is used:

sql:40, DTxnLogger (io.ebeaninternal.server.logger)
logSql:443, ImplicitReadOnlyTransaction (io.ebeaninternal.server.transaction)
logSql:405, CQueryEngine (io.ebeaninternal.server.query)
findMany:348, CQueryEngine (io.ebeaninternal.server.query)
findMany:126, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findList:403, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1430, DefaultServer (io.ebeaninternal.server.core)
findList:1409, DefaultServer (io.ebeaninternal.server.core)
executeQuery:149, DefaultBeanLoader (io.ebeaninternal.server.core)
loadMany:37, DefaultBeanLoader (io.ebeaninternal.server.core)
loadMany:462, DefaultServer (io.ebeaninternal.server.core)
loadSecondaryQuery:98, DLoadManyContext (io.ebeaninternal.server.loadcontext)
executeSecondaryQueries:192, DLoadContext (io.ebeaninternal.server.loadcontext)
executeSecondaryQueries:121, OrmQueryRequest (io.ebeaninternal.server.core)
findMany:357, CQueryEngine (io.ebeaninternal.server.query)
findMany:126, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findList:403, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1430, DefaultServer (io.ebeaninternal.server.core)
findOne:1060, DefaultServer (io.ebeaninternal.server.core)
findOne:1569, DefaultOrmQuery (io.ebeaninternal.server.querydefn)
findOne:429, DefaultExpressionList (io.ebeaninternal.server.expression)
byUUID:54, UserFinder (com.nedap.healthcare.administration.authorization.finder)
...

@tbee
Copy link
Contributor Author

tbee commented May 31, 2024

It seems this setup maybe intended for use with a ReadonlyDatasource. But setting that up shows that the two nested getConnections both claim from the readonly datasource, thus does not solve the problem. (The first working get/return claims from the normal pool.)

@tbee
Copy link
Contributor Author

tbee commented Jun 3, 2024

Below are the two stacktraces of the two claims for a connection without returning in between.

getConnection:276, SemaphoreConcurrentLinkedDequeManagedConnectionPool (org.jboss.jca.core.connectionmanager.pool.mcp)
getSimpleConnection:640, AbstractPool (org.jboss.jca.core.connectionmanager.pool)
getConnection:605, AbstractPool (org.jboss.jca.core.connectionmanager.pool)
getManagedConnection:624, AbstractConnectionManager (org.jboss.jca.core.connectionmanager)
getManagedConnection:440, TxConnectionManagerImpl (org.jboss.jca.core.connectionmanager.tx)
allocateConnection:789, AbstractConnectionManager (org.jboss.jca.core.connectionmanager)
getConnection:151, WrapperDataSource (org.jboss.jca.adapters.jdbc)
getConnection:64, WildFlyDataSource (org.jboss.as.connector.subsystems.datasources)
createReadOnlyTransaction:32, TransactionFactoryBasicWithRead (io.ebeaninternal.server.transaction)
createReadOnlyTransaction:294, TransactionManager (io.ebeaninternal.server.transaction)
createReadOnlyTransaction:2153, DefaultServer (io.ebeaninternal.server.core)
initTransIfRequired:219, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1429, DefaultServer (io.ebeaninternal.server.core)
findOne:1060, DefaultServer (io.ebeaninternal.server.core)
findOne:1569, DefaultOrmQuery (io.ebeaninternal.server.querydefn)
findOne:429, DefaultExpressionList (io.ebeaninternal.server.expression)
byUUID:54, UserFinder (com.nedap.healthcare.administration.authorization.finder)
byUuid:607, UserResource (com.nedap.healthcare.administration.rest)
userByUuid:155, UserResource (com.nedap.healthcare.administration.rest)
...

getConnection:276, SemaphoreConcurrentLinkedDequeManagedConnectionPool (org.jboss.jca.core.connectionmanager.pool.mcp)
getSimpleConnection:640, AbstractPool (org.jboss.jca.core.connectionmanager.pool)
getConnection:605, AbstractPool (org.jboss.jca.core.connectionmanager.pool)
getManagedConnection:624, AbstractConnectionManager (org.jboss.jca.core.connectionmanager)
getManagedConnection:440, TxConnectionManagerImpl (org.jboss.jca.core.connectionmanager.tx)
allocateConnection:789, AbstractConnectionManager (org.jboss.jca.core.connectionmanager)
getConnection:151, WrapperDataSource (org.jboss.jca.adapters.jdbc)
getConnection:64, WildFlyDataSource (org.jboss.as.connector.subsystems.datasources)
createReadOnlyTransaction:32, TransactionFactoryBasicWithRead (io.ebeaninternal.server.transaction)
createReadOnlyTransaction:294, TransactionManager (io.ebeaninternal.server.transaction)
createReadOnlyTransaction:2153, DefaultServer (io.ebeaninternal.server.core)
initTransIfRequired:219, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1429, DefaultServer (io.ebeaninternal.server.core)
findList:1409, DefaultServer (io.ebeaninternal.server.core)
executeQuery:149, DefaultBeanLoader (io.ebeaninternal.server.core)
loadMany:37, DefaultBeanLoader (io.ebeaninternal.server.core)
loadMany:462, DefaultServer (io.ebeaninternal.server.core)
loadSecondaryQuery:98, DLoadManyContext (io.ebeaninternal.server.loadcontext)
executeSecondaryQueries:192, DLoadContext (io.ebeaninternal.server.loadcontext)
executeSecondaryQueries:121, OrmQueryRequest (io.ebeaninternal.server.core)
findMany:357, CQueryEngine (io.ebeaninternal.server.query)
findMany:126, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findList:403, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1430, DefaultServer (io.ebeaninternal.server.core)
findOne:1060, DefaultServer (io.ebeaninternal.server.core)
findOne:1569, DefaultOrmQuery (io.ebeaninternal.server.querydefn)
findOne:429, DefaultExpressionList (io.ebeaninternal.server.expression)
byUUID:54, UserFinder (com.nedap.healthcare.administration.authorization.finder)
byUuid:607, UserResource (com.nedap.healthcare.administration.rest)
userByUuid:155, UserResource (com.nedap.healthcare.administration.rest)
...

The second stacktrace has two different requests objects in DefaultServer line 1429. They are constructed just above in line 1414. It would make sense that the second request reuses the readonly connection obtained by the first request.

Under EBean 12 this nesting indeed does not happen. And if an explicit JTA transaction is started, both request use that connection.

@tbee tbee changed the title Race condition EBean 14? Race condition EBean 14 Jun 3, 2024
@tbee tbee changed the title Race condition EBean 14 Race condition EBean 14.0.2 Jun 3, 2024
@tbee tbee changed the title Race condition EBean 14.0.2 Race condition EBean 14.3.0 Jun 3, 2024
@tbee tbee changed the title Race condition EBean 14.3.0 Race condition EBean 14.0.2 Jun 3, 2024
@tbee tbee changed the title Race condition EBean 14.0.2 Race condition EBean 14 Jun 3, 2024
@tbee
Copy link
Contributor Author

tbee commented Jun 6, 2024

I was able to patch the behaviour by introducing a ThreadLocal variable in OrmQueryRequest.initTransIfRequired and solely for createReadOnlyTransaction store the first transaction within a thread, and return that on subsequent calls. Does not seem like the correct way to fix it, but it appears to work.

@tbee
Copy link
Contributor Author

tbee commented Jun 6, 2024

Alternatively one can add to e.g. LoadManyRequest.createQuery code to use the existing transaction:

    if (this.transaction() != null) {
      query.usingTransaction(transaction);
    }

Or in DefaultBeanLoader

  void loadMany(LoadManyRequest loadRequest) {
    SpiQuery<?> query = loadRequest.createQuery(server);
    query.usingTransaction(loadRequest.transaction());
    executeQuery(loadRequest, query);
    loadRequest.postLoad();
  }

This feels like a better approach. Where the last one seems like it could be the fix, because it mirrors loadBean in the same class.

tbee added a commit to nedap/ebean that referenced this issue Jun 7, 2024
rbygrave added a commit that referenced this issue Jun 7, 2024
Fix such that LoadManyRequest uses the parent requests transaction rather
than obtain a new read only transaction to perform the fetch query.
rbygrave added a commit that referenced this issue Jun 7, 2024
…ogic into LoadBeanRequest

Move the query creation, using transaction and configure into LoadBeanRequest. This code then looks more like that of LoadManyRequest.
@rbygrave rbygrave added this to the 14.3.1 milestone Jun 7, 2024
@rbygrave rbygrave added the bug label Jun 7, 2024
rbygrave added a commit that referenced this issue Jun 7, 2024
#3412 Use existing/parent transaction with fetch query on ToMany paths
@tbee
Copy link
Contributor Author

tbee commented Jun 10, 2024

Any idea when a bugfix release will come out?

@rbygrave
Copy link
Member

Should be on the way to central, so should be available in about 20 minutes.

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

Successfully merging a pull request may close this issue.

2 participants