I'm working on an web application based on spring (spring-boot 1.5.13.RELEASE) connect to a MySQL 8 database. We choose to work with tomcat jdbc pool (the default pool for spring-boot). Production department ask us to work on a solution to avoid incomplete transaction using rollback-on-return property (we've set auto-commit=false too).
We can't just use annotation oriented transaction. We have to manage some of them programmatically. So we thought that the use of rollback-on-return will avoid "pending" transaction. Unfortunately, during test phase, we discover that if a request create a "pending" transaction, the end of the request is not going with the return of the connection. And thus, there is no rollback!
I already test if the connection is closed on a normal case, and so it is.
Here is my example code:
public CommandLineRunner commandLineRunner(CustomerManager customerManager, EngineManager engineManager, DataSource dataSource) {
return (String... args) -> {
log.info("Start commandLineRunner" + engineManager.getTransactionPartEngineInnodbStatus());
Thread t = new Thread(() -> {
try {
customerManager.processII_notcomplete();
} catch (Exception e) {
System.err.println(e.getMessage());
}
});
t.start();
t.join();
log.info("End commandLineRunner" + engineManager.getTransactionPartEngineInnodbStatus());
};
}
public void processII_notcomplete() {
TransactionStatus status = transactionManager.getTransaction(new DefaultTransactionDefinition(TransactionDefinition.PROPAGATION_REQUIRED));
log.info("processII [START]");
Customer customer = customerRepository.findOne(1L);
customer.lastName = "De " + customer.lastName;
customerRepository.save(customer);
log.info("processII: customerRepository.save(customer)" + engineManager.getTransactionPartEngineInnodbStatus() + "\n");
// Intentionally don't commit the transaction to create the use case
log.info("processII [END]");
}
I've found a JdbcInterceptor to log the borrow and the return of the connection:
public class JDBCLogInterceptor extends JdbcInterceptor {
private static final Logger log = LoggerFactory.getLogger(JDBCLogInterceptor.class);
@Override
public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
if (log.isDebugEnabled()) {
String name = method.getName();
if (CLOSE_VAL.equals(name)) {
log.debug(String.format("Returning Connection to Pool [%s]", proxy));
}
}
return super.invoke(proxy, method, args);
}
@Override
public void reset(ConnectionPool connPool, PooledConnection conn) {
if (connPool != null && conn != null) {
if (log.isDebugEnabled()) {
log.debug(String.format("Getting Connection [%s], Pool active=[%s], idle=[%s]", conn.toString(),
connPool.getActive(), connPool.getIdle()));
}
}
}
@Override
public void disconnected(ConnectionPool connPool, PooledConnection conn, boolean finalizing) {
if (connPool != null && conn != null) {
if (log.isDebugEnabled()) {
log.debug(String.format("Closing Connection [%s], Pool active=[%s], idle=[%s]", conn.toString(),
connPool.getActive(), connPool.getIdle()));
}
}
}
}
And here is the pertinent log part:
ERROR 2019/01/29 16:28:13.975 - no-request --- mova.jpatest.JPATestConfig - Start commandLineRunner
------------
TRANSACTIONS
------------
Trx id counter 269691
Purge done for trx's n:o < 269691 undo n:o < 0 state: running but idle
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 283703119152960, not started
0 lock struct(s), heap size 1136, 0 row lock(s) - [no-one]
DEBUG 2019/01/29 16:28:13.985 - no-request --- mova.jpatest.jdbc.JDBCLogInterceptor - Getting Connection [PooledConnection[com.p6spy.engine.wrapper.ConnectionWrapper@63bf9fce]], Pool active=[1], idle=[9] - [no-one]
INFO 2019/01/29 16:28:13.989 - no-request --- mova.jpatest.manager.CustomerManager - processII [START] - [no-one]
INFO 2019/01/29 16:28:13.995 - no-request --- p6spy - statement --- select customer0_.id as id1_0_0_, customer0_.first_name as first_na2_0_0_, customer0_.last_name as last_nam3_0_0_ from customer customer0_ where customer0_.id=? - select customer0_.id as id1_0_0_, customer0_.first_name as first_na2_0_0_, customer0_.last_name as last_nam3_0_0_ from customer customer0_ where customer0_.id=1 - 01-29-19 16:28:13:995-2 [connection 8] - [no-one]
INFO 2019/01/29 16:28:14.029 - no-request --- p6spy - statement --- update customer set first_name=?, last_name=? where id=? - update customer set first_name='Jack', last_name='De De De De De De De Bauer' where id=1 - 01-29-19 16:28:14:29-0 [connection 8] - [no-one]
INFO 2019/01/29 16:28:14.039 - no-request --- p6spy - statement --- show engine innodb status; - show engine innodb status; - 01-29-19 16:28:14:39-6 [connection 8] - [no-one]
INFO 2019/01/29 16:28:14.039 - no-request --- mova.jpatest.manager.CustomerManager - processII: customerRepository.save(customer)
------------
TRANSACTIONS
------------
Trx id counter 269692
Purge done for trx's n:o < 269691 undo n:o < 0 state: running but idle
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 269691, ACTIVE 0 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 624, OS thread handle 20236, query id 47274 localhost 127.0.0.1 mohicane starting
show engine innodb status
Trx read view will not see trx with id >= 269691, sees < 269691
- [no-one]
INFO 2019/01/29 16:28:14.039 - no-request --- mova.jpatest.manager.CustomerManager - processII [END] - [no-one]
DEBUG 2019/01/29 16:28:14.039 - no-request --- mova.jpatest.jdbc.JDBCLogInterceptor - Getting Connection [PooledConnection[com.p6spy.engine.wrapper.ConnectionWrapper@3d646e1a]], Pool active=[2], idle=[8] - [no-one]
INFO 2019/01/29 16:28:14.045 - no-request --- p6spy - statement --- show engine innodb status; - show engine innodb status; - 01-29-19 16:28:14:45-2 [connection 9] - [no-one]
DEBUG 2019/01/29 16:28:14.045 - no-request --- mova.jpatest.jdbc.JDBCLogInterceptor - Returning Connection to Pool [ProxyConnection[PooledConnection[com.p6spy.engine.wrapper.ConnectionWrapper@3d646e1a]]] - [no-one]
ERROR 2019/01/29 16:28:14.045 - no-request --- mova.jpatest.JPATestConfig - End commandLineRunner
------------
TRANSACTIONS
------------
Trx id counter 269692
Purge done for trx's n:o < 269691 undo n:o < 0 state: running but idle
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 283703119153840, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 269691, ACTIVE 0 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 624, OS thread handle 20236, query id 47274 localhost 127.0.0.1 mohicane
Trx read view will not see trx with id >= 269691, sees < 269691 - [no-one]
My questions are:
- Is there a way to make sure that pending transaction always be complete like we've expected with rollback-on-return?
- Can we detect and return "unreturned" connection in this case?
- It seems strange that such property exists and not managed in this case? Why would we use a rollback after a transaction we've already commit or rollback? Is there something I don't understand (sure it is :p ) ?
NB: Plese don't mind the ERROR log level, I'm a little color blind.
Edit:
I try through an interceptor to detect current active Transaction using TransactionSynchronizationManager.isActualTransactionActive(). This way, I find the unfinished ones, but when I try to get it with TransactionAspectSupport.currentTransactionStatus() it return me null??? Can't understand...
Simplification
Is there a way to detect and rollback a forgotten programmatic transaction (as shown in the code below)?
