Search code examples
javapostgresqlmybatistransactional

Why does myBatis+postgresql 9.3 issue a ROLLBACK even if the query succeeds?

I have a piece of Java code that uses myBatis, postgresql 9.3 server, and postgresql-9.3-1100-jdbc41 JDBC driver. We're also using mybatis-guice for @Transactional support. Until now we've been using only Serializable transactions, and now we want to put queries that only read from the db in a less strict isolation level, such as 'read committed'. So, some of the @Transactional annotation use SERIALIZABLE, some of them use READ_COMMITTED. There are also nested calls.

So, I have this in the postgresql server log: 

2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1268 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT
                *
            FROM
                customer.accounts
            WHERE
--
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : UPDATE
                customer.cities
            SET
                name = $1,
                ledger_id = $2,
--
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: ......
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : SELECT
                l.*
                 ,
                cc.id as cost_center_id,
                cc.description as cost_center_description,
--
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = .....
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : UPDATE
                customer.ledgers
            SET
                internal_ledger_number = $1
                 ,
--
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ...........
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : SELECT DISTINCT
                role
            FROM customer.user_roles ur INNER JOIN customer.user_to_accounts_to_user_roles uur ON (ur.id=uur.role_id)
            WHERE
                user_id=$1
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = .......
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute S_2: ROLLBACK
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT 
                id
            FROM
            customer.user_roles
            WHERE role=$1
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ......
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : INSERT INTO customer.user_to_accounts_to_user_roles 
            (user_id, account_id, role_id) 
            values 
            ($1, $2, $3)
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ........
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=1726979 pid=1949 appName=entity_manager LOG:  execute S_1: COMMIT



2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1271 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT
                *
            FROM
                customer.cities
            WHERE
--
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ......
2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute S_1: COMMIT

(This is a snippet, filtered by grepping for the sessionId and using --after-context - that's why some queries seem unterminated, but believe me, they're valid queries). So I have a list of successful queries, and at some point there's a ROLLBACK issued. Then the code continues with the rest of the queries. So I don't seem to have any exceptions in the code. And it seems like that ROLLBACK is issued out of the blue.

How can this happen?
This happens like 1 out of 10 times, 9 out of 10 times everything works ok (with the same data). The code is multi-threaded.

I can provide other details, no problem.

Solution

  • I've found the reason in the meantime.

    It turns out inside a method annotated with @Transactional (let's call this methodA) there was another method annotated with @Transactional as well (let's call this methodB). This inner method (methodB) threw an exception, the exception was cought in methodA and the code happily went on. However, as soon as myBatis saw the exception it would rollback the entire transaction.

    Something like this:

    methodA (@Transactional)
begin
select * ....
update .....
methodB: select .... 
methodB: throw exception -> myBatis calls rollback
methodA: catch exception, go on
methodA: other code