Почему myBatis + postgresql 9.3 выдает ROLLBACK, даже если запрос завершается успешно?

Question

У меня есть кусок кода Java, который использует myBatis, сервер postgresql 9.3 и драйвер JDBC postgresql-9.3-1100-jdbc41. Мы также используем mybatis-guice для поддержки @Transactional. До сих пор мы использовали только транзакции Serializable, и теперь мы хотим поставить запросы, которые читаются только с db на менее строгом уровне изоляции, например «read commit». Итак, некоторые из аннотаций @Transactional используют SERIALIZABLE, некоторые из них используют READ_COMMITTED. Есть также вложенные вызовы.

Итак, у меня есть это в журнале PostgreSQL сервера:

 
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 

(Это фрагмент, фильтруется для оглавлению SESSIONID и используя --after-контекст - вот почему некоторые запросы кажутся незавершенными, но поверьте мне, они действительные запросы). Итак, у меня есть список успешных запросов, и в какой-то момент выдается ROLLBACK. Затем код продолжается с остальными запросами. Поэтому у меня нет никаких исключений в коде. И похоже, что ROLLBACK выпущен из синего.

Как это может произойти?
Это происходит как 1 из 10 раз, 9 из 10 раз все работает нормально (с теми же данными). Код многопоточный.

Я могу предоставить другие подробности, никаких проблем.

Answer 1

Я нашел причину тем временем.

Внутри метода, аннотированного с помощью @Transactional (назовем этот методA), был еще один метод, аннотированный с помощью @Transactional (назовем этот методB). Этот внутренний метод (methodB) бросил исключение, исключение было принято в методе А, и код с радостью продолжился. Однако, как только myBatis увидит исключение, он отбросит всю транзакцию.

Что-то вроде этого:

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