spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.81k stars 38.18k forks source link

`JdbcTemplate` closes connection after update and Hikari performs a rollback before `JpaTransactionManager` commit #33993

Open BbIKTOP opened 4 days ago

BbIKTOP commented 4 days ago

Affects: Spring Boot 3.3.5

I asked on stackoverflow and also found similar questions there:

https://stackoverflow.com/questions/78022351/spring-boot-jpa-transaction-is-committing-but-record-is-not-getting-inserted https://stackoverflow.com/questions/78863344/frequent-rollback-on-connection-close-in-spring-boot-with-hikaricp-and-mariadb

The problem:

Simple table:

CREATE TABLE table_master
(
    id       INTEGER NOT NULL,
    name     VARCHAR(200),
    CONSTRAINT t_master_pk PRIMARY KEY (id)
);

Test:

@SpringBootTest
@TestMethodOrder(MethodOrderer.OrderAnnotation.class)
@Slf4j
class JdbcTest {

    private DataSource fbDataSource;

    @Autowired
    private PlatformTransactionManager transactionManager;

    @BeforeEach
    public void setUp() {
        HikariConfig config = new HikariConfig();
        config.setJdbcUrl("jdbc:firebirdsql://localhost:3055//opt/fb/db/DBGDB");
        config.setUsername("user");
        config.setPassword("passwd");
        config.setAutoCommit(false);
        fbDataSource = new HikariDataSource(config);
    }

    private static final String insertQuery = "INSERT INTO table_master(id, name) VALUES(?, ?)";
    private static final String cntQuery = "SELECT COUNT(*) FROM table_master";

    @Test
    public void testFbLoad() throws SQLException {
        JdbcTemplate fbJdbcTemplate = new JdbcTemplate(fbDataSource);
        DefaultTransactionDefinition def = new DefaultTransactionDefinition();
        def.setPropagationBehavior(DefaultTransactionDefinition.PROPAGATION_REQUIRES_NEW);
        def.setIsolationLevel(DefaultTransactionDefinition.ISOLATION_READ_COMMITTED);
        TransactionStatus status = transactionManager.getTransaction(def);

        if (fbJdbcTemplate.update(insertQuery, 1, "Row") == 0) {
            throw new RuntimeException("Cannot insert row");
        }
        transactionManager.commit(status);

        Integer cnt = fbJdbcTemplate.queryForObject(cntQuery, Integer.class);
        log.info("Rows in table_master: {}", cnt);
    }

Log:

2024-11-30T04:10:31.534+02:00 DEBUG 15966 --- [    Test worker] o.h.e.t.internal.TransactionImpl         : On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2024-11-30T04:10:31.535+02:00 DEBUG 15966 --- [    Test worker] o.h.e.t.internal.TransactionImpl         : begin
2024-11-30T04:10:31.536+02:00 DEBUG 15966 --- [    Test worker] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@ea34dee]
2024-11-30T04:10:31.536+02:00 DEBUG 15966 --- [    Test worker] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2024-11-30T04:10:31.537+02:00 DEBUG 15966 --- [    Test worker] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [INSERT INTO table_master(id, name) VALUES(?, ?)]
2024-11-30T04:10:31.537+02:00 DEBUG 15966 --- [    Test worker] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2024-11-30T04:10:31.544+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.553+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.553+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.567+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.568+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.570+02:00 DEBUG 15966 --- [    Test worker] o.f.jaybird.xca.FBManagedConnection      : End called: Xid[413118226]
2024-11-30T04:10:31.573+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.573+02:00 DEBUG 15966 --- [    Test worker] o.f.gds.ng.wire.AbstractWireOperations   : readStatusVector arg:isc_arg_gds int: 0
2024-11-30T04:10:31.574+02:00 DEBUG 15966 --- [    Test worker] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Executed rollback on connection org.firebirdsql.jdbc.FBConnection@394e21b9 due to dirty commit state on close().
2024-11-30T04:10:31.574+02:00 DEBUG 15966 --- [    Test worker] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2024-11-30T04:10:31.574+02:00 DEBUG 15966 --- [    Test worker] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(865867007<open>)]
2024-11-30T04:10:31.574+02:00 DEBUG 15966 --- [    Test worker] o.h.e.t.internal.TransactionImpl         : committing
2024-11-30T04:10:31.575+02:00 DEBUG 15966 --- [    Test worker] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(865867007<open>)] after transaction

Problem:

No data inserted due to:

2024-11-30T04:10:31.574+02:00 DEBUG 15966 --- [    Test worker] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Executed rollback on connection org.firebirdsql.jdbc.FBConnection@394e21b9 due to dirty commit state on close().

Reason:

JdbcTemplate closes connection in the update method. Hikari rolls the transaction back due to the connection' dirty state then. Then JpaTransactionManager tries to commit it but it was already rolled back. So, the example from the Spring docs is not working.

Stack:

doCloseConnection:406, DataSourceUtils (org.springframework.jdbc.datasource)
doReleaseConnection:393, DataSourceUtils (org.springframework.jdbc.datasource)
releaseConnection:360, DataSourceUtils (org.springframework.jdbc.datasource)
beforeCompletion:525, DataSourceUtils$ConnectionSynchronization (org.springframework.jdbc.datasource)
triggerBeforeCompletion:108, TransactionSynchronizationUtils (org.springframework.transaction.support)
triggerBeforeCompletion:996, AbstractPlatformTransactionManager (org.springframework.transaction.support)
processCommit:776, AbstractPlatformTransactionManager (org.springframework.transaction.support)
commit:758, AbstractPlatformTransactionManager (org.springframework.transaction.support)
testFbLoad:105, JdbcTest (com.freewayfleet.dbreplicator)
quaff commented 2 days ago

Can not be reproduced by H2.

import static org.assertj.core.api.Assertions.assertThat;

import java.sql.SQLException;

import javax.sql.DataSource;

import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.jdbc.core.JdbcTemplate;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.jdbc.Sql;
import org.springframework.transaction.PlatformTransactionManager;
import org.springframework.transaction.TransactionStatus;
import org.springframework.transaction.support.DefaultTransactionDefinition;

@org.springframework.boot.test.autoconfigure.jdbc.JdbcTest
@ContextConfiguration(classes = JdbcTest.class)
@Sql(statements = "CREATE TABLE table_master(id INTEGER NOT NULL,name VARCHAR(200),CONSTRAINT t_master_pk PRIMARY KEY (id))")
class JdbcTest {

    @Autowired
    private DataSource dataSource;

    @Autowired
    private PlatformTransactionManager transactionManager;

    private static final String insertQuery = "INSERT INTO table_master(id, name) VALUES(?, ?)";
    private static final String cntQuery = "SELECT COUNT(*) FROM table_master";

    @Test
    public void test() throws SQLException {
        JdbcTemplate fbJdbcTemplate = new JdbcTemplate(dataSource);
        DefaultTransactionDefinition def = new DefaultTransactionDefinition();
        def.setPropagationBehavior(DefaultTransactionDefinition.PROPAGATION_REQUIRES_NEW);
        def.setIsolationLevel(DefaultTransactionDefinition.ISOLATION_READ_COMMITTED);
        TransactionStatus status = transactionManager.getTransaction(def);

        if (fbJdbcTemplate.update(insertQuery, 1, "Row") == 0) {
            throw new RuntimeException("Cannot insert row");
        }
        transactionManager.commit(status);

        Integer cnt = fbJdbcTemplate.queryForObject(cntQuery, Integer.class);
        assertThat(cnt).isEqualTo(1);
    }
}
BbIKTOP commented 1 day ago

Looks like it fails with custom datasource

mdeinum commented 1 day ago

As mentioned in the stackoverflow issue, the datasource isnt even known to Spring and the PlatformTransactionManager in use is tied to another DataSource so won't manage the transactions. As the auto-commit is set to false you are basically running without a transaction, no transaction no persisting.