rxjava2-jdbc icon indicating copy to clipboard operation
rxjava2-jdbc copied to clipboard

Published 20 hours ago • verified publisher icon davidmoten

Transaction is not committing

Open lz000 opened this issue 6 years ago • 3 comments
trafficstars

I have a function that executes 2 updates in a transaction. After running the code, I don't see any change in the db. I suspect the transaction is not committed. I'm sure there is no error with the queries since doOnError is not fired. Removing transaction would work. Any idea why transaction not working?

below is my code

public Mono<Integer> update() {
        Flowable<Integer> updates = db.update("UPDATE ...")
                .parameters(...)
                .transacted()
                .counts()
                .doOnError(e-> {
                                LOGGER.debug(e);
               })
                .flatMap(tx -> {
                    return tx.update("UPDATE ...")
                            .parameters(...)
                            .counts()
                            .doOnError(e-> {
                                LOGGER.debug(e);
                            });
                });

        return Mono.from(updates);
}

below is the log

Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.jdbc.SqlInfo][] - sqlAfterSubs=<UPDATE QUERY>
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.jdbc.TransactedUpdateBuilder][] - creating deferred flowable
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - subscribed
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain called
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain loop starting
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - requested=1
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - poll of available members returns DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - trying to emit member
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - schedule.now=1557250484152, lastCheck=1557250476191
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - queueing member for health check DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - scheduling check of DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - poll of available members returns null
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - scheduling member creation
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - performing health check on DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - poll of available members returns null
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - insufficient demand to initialize DecoratingMember [value=null]
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain called
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain loop starting
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - requested=1
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - poll of available members returns null
Thread: pool-2-thread-3] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - insufficient demand to initialize DecoratingMember [value=null]
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - creating value
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain called
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain loop starting
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - requested=1
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - poll of available members returns DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - trying to emit member
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - schedule.now=1557250484155, lastCheck=1557250484155
Thread: pool-2-thread-4] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - no health check required for DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@65d2b0cb]
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - creating new TransactedConnection
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedConnection][] - constructing TransactedConnection from org.davidmoten.rx.jdbc.pool.internal.PooledConnection@140a7cbd, 1
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - <UPDATE QUERY>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.SqlInfo][] - sqlAfterSubs=<UPDATE QUERY>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - preparing statement: <UPDATE QUERY>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - setting parameter ...
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - batch added with [...]
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - checking in DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@779e8a73]
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.DecoratingMember][] - scheduled release in 1800000ms of DecoratingMember [value=com.mysql.cj.jdbc.ConnectionImpl@779e8a73]
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain called
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain loop starting
Thread: pool-2-thread-5] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - requested=0
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - batch executed
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedConnection][] - forking connection
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedConnection][] - constructing TransactedConnection from org.davidmoten.rx.jdbc.pool.internal.PooledConnection@140a7cbd, 3
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.SqlInfo][] - sqlAfterSubs=<UPDATE QUERY 2>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedUpdateBuilder][] - creating deferred flowable
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - <UPDATE QUERY 2>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.SqlInfo][] - sqlAfterSubs=<UPDATE QUERY 2>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - preparing statement: <UPDATE QUERY 2>
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - setting parameter ...
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - batch added with [...]
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Update][] - batch executed
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain called
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - drain loop starting
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.pool.MemberSingle][] - requested=0
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - closing org.davidmoten.rx.jdbc.TransactedPreparedStatement@53da613f
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - closing TransactedConnection [con=org.davidmoten.rx.jdbc.pool.internal.PooledConnection@140a7cbd, counter=4]
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedConnection][] - TransactedConnection attempt close
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - closing org.davidmoten.rx.jdbc.TransactedPreparedStatement@5340c1b2
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.Util][] - closing TransactedConnection [con=org.davidmoten.rx.jdbc.pool.internal.PooledConnection@140a7cbd, counter=4]
Thread: pool-2-thread-6] DEBUG [org.davidmoten.rx.jdbc.TransactedConnection][] - TransactedConnection attempt close

lz000 avatar May 07 '19 17:05 lz000

Thanks for that, debug logs help. I'm very short on bandwidth to work on rxjava2-jdbc issues at the moment though they are on my backlog. If you can do some more work on it great.

davidmoten avatar May 08 '19 04:05 davidmoten

I found that the reason is the transaction is never completed, which is why commit() is never invoked. I'm using this with Spring webflux. It looks like doOnComplete is never invoked with spring webflux. I have to specifically trigger subscribe() and make it blocking.

Flowable<Tx<Integer>> updates = db.update("UPDATE ...")
                .parameters(...)
                .transacted()
                .counts()
                .doOnError(e-> {
                                LOGGER.debug(e);
               })
                .flatMap(tx -> {
                    return tx.update("UPDATE ...")
                            .parameters(...)
                            .counts()
                            .doOnError(e-> {
                                LOGGER.debug(e);
                            });
                });

updates.subscribe();

However, I found another issue. I deliberately made the second query wrong to test rollback. Both queries were not committed which is expected (commit() was not called so counter was not decreased). From the log I see TransactedConnection attempt close but not TransactedConnection close. Debugged the code, this.counter is 4 not 0, which is preventing transaction from close. It looks like the sql error is not handled properly in transaction. So next time I call this function again, I got error com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction. Any idea?

lz000 avatar May 08 '19 15:05 lz000

Looks like in TransactedUpdateBuilder.createFlowable before doOnComplete will be called, we will receive one more item with isComplete() = true and it will be stored in doOnNext.

Tx with isComplete() = true come from Tx.toTx if (n.isOnComplete()) branch (line 38)

Because isComplete() true - commit will not be called

rigidsh avatar Oct 28 '19 10:10 rigidsh