MapperFactoryBean problem

[Kari Pulkka]

Hi,

I have a problem regarding updates using an optimistic locking policy.

In my Spring config file I have:

        <bean id="timeBasedEmployeeMapper"
class="org.mybatis.spring.mapper.MapperFactoryBean">
           <property name="mapperInterface"
value="my.sample.TimeBasedEmployeeMapper" />
           <property name="sqlSessionFactory" ref="sqlSessionFactory" />
        </bean>

The mapper interface is as follows:

package my.sample;
import java.util.Collection;
public interface TimeBasedEmployeeMapper {
        public Collection<TimeBasedEmployee> findEmployees(String lastName);
        public Integer insertEmployee(TimeBasedEmployee employee);
        public Integer updateEmployee(TimeBasedEmployee employee);
        public TimeBasedEmployee loadEmployee(long id);
}

The update function:
    <update id="updateEmployee"
parameterType="my.sample.TimeBasedEmployee">
        update T_TIMEBASED_EMPLOYEES
        set EMP_MODIFIED_TIME = CURRENT_TIMESTAMP, EMP_FIRST_NAME =
#{firstName}, EMP_LAST_NAME = #{lastName},
            EMP_PHONE = #{phone}, EMP_EMAIL = #{email}
        where EMP_ID = #{id} and EMP_MODIFIED_TIME = #{modifiedTime}
    </update>

When I run the following test, the test fails, because no exception is
raised from the latter update. I I comment out the expected result
from the @Test -annotation, the test completes just fine. Obviously
this is not how it should work.
        @Test(expected = OptimisticLockingFailureException.class)
        @Transactional
        public void testTimeBasedOptimisticLocking() {
                TimeBasedEmployee e1 = tr.loadEmployee(1);
                TimeBasedEmployee e2 = tr.loadEmployee(1);
                e2.setLastName("Jones");
                tr.updateEmployee(e2);
                tr.updateEmployee(e1);
        }

If I run a similar test using SqlSessionTemplate and DAOs using the
sql-snippet above, it works correctly. Any pointers? Thanks in
advance!

-Kari

[Eduardo Macarron]

Hi Kari, please enable the log and post both cases with and without
the MapperFactoryBean.

[Kari Pulkka]

Here is the relevant log using MapperFactoryBean:

2012-04-25 09:57:28,536 INFO
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Began transaction (1): transaction manager
[org.springframework.jdbc.datasource.DataSourceTransactionManager@1169fb2];
rollback [true]
2012-04-25 09:57:28,551 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Creating a new SqlSession
2012-04-25 09:57:28,551 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Registering transaction synchronization for SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,551 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Bound value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
to thread [main]
2012-04-25 09:57:28,583 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@1d2b8e] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@1efa490]
bound to thread [main]
2012-04-25 09:57:28,583 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@1d2b8e] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@1efa490]
bound to thread [main]
2012-04-25 09:57:28,583 DEBUG
[org.mybatis.spring.transaction.SpringManagedTransaction] - JDBC
Connection [org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID
= 193), (SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID =
null) ] will be managed by Spring
2012-04-25 09:57:28,583 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.loadEmployee]
- ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:57:28,583 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.loadEmployee]
- ==>  Preparing: select EMP_ID, EMP_MODIFIED_TIME, EMP_FIRST_NAME,
EMP_LAST_NAME, EMP_PHONE, EMP_EMAIL from T_TIMEBASED_EMPLOYEES where
EMP_ID=?
2012-04-25 09:57:28,614 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.loadEmployee]
- ==> Parameters: 1(Long)
2012-04-25 09:57:28,629 TRACE
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.loadEmployee]
- <==    Columns: EMP_ID, EMP_MODIFIED_TIME, EMP_FIRST_NAME,
EMP_LAST_NAME, EMP_PHONE, EMP_EMAIL
2012-04-25 09:57:28,629 TRACE
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.loadEmployee]
- <==        Row: 1, 2010-03-01 00:00:00.123, Mikko, Mallikas,
010-1234567, [hidden email]
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a] from
current transaction
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,645 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,645 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a] from
current transaction
2012-04-25 09:57:28,645 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:57:28,645 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ==>  Preparing: update T_TIMEBASED_EMPLOYEES set EMP_MODIFIED_TIME =
CURRENT_TIMESTAMP, EMP_FIRST_NAME = ?, EMP_LAST_NAME = ?, EMP_PHONE
= ?, EMP_EMAIL = ? where EMP_ID = ? and EMP_MODIFIED_TIME = ?
2012-04-25 09:57:28,645 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ==> Parameters: Mikko(String), Åberg(String), 010-1234567(String),
[hidden email](String), 1(Long), 2010-03-01
00:00:00.123(Timestamp)
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,661 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,661 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a] from
current transaction
2012-04-25 09:57:28,661 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:57:28,661 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ==>  Preparing: update T_TIMEBASED_EMPLOYEES set EMP_MODIFIED_TIME =
CURRENT_TIMESTAMP, EMP_FIRST_NAME = ?, EMP_LAST_NAME = ?, EMP_PHONE
= ?, EMP_EMAIL = ? where EMP_ID = ? and EMP_MODIFIED_TIME = ?
2012-04-25 09:57:28,661 DEBUG
[my.sample.persistence.ibatis.support.TimeBasedEmployeeMapper.updateEmployee]
- ==> Parameters: Mikko(String), Åberg(String), 010-1234567(String),
[hidden email](String), 1(Long), 2010-03-01
00:00:00.123(Timestamp)
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
bound to thread [main]
2012-04-25 09:57:28,661 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,661 TRACE
[org.springframework.test.context.TestContextManager] -
afterTestMethod(): instance
[my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd],
method [public void
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest.testTimeBasedOptimisticLocking()],
exception [java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException]
2012-04-25 09:57:28,661 DEBUG
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- No method-level @Rollback override: using default rollback [true]
for test context [[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientMapperIntegrationTest,
testException = java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException,
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]]
2012-04-25 09:57:28,661 TRACE
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Ending transaction for test context [[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientMapperIntegrationTest,
testException = java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException,
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]];
transaction manager
[org.springframework.transaction.support.DefaultTransactionStatus@ea3cdf];
rollback [true]
2012-04-25 09:57:28,661 TRACE
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Triggering beforeCompletion synchronization
2012-04-25 09:57:28,661 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Initiating transaction rollback
2012-04-25 09:57:28,661 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Rolling back JDBC transaction on Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:57:28,661 TRACE
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Triggering afterCompletion synchronization
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Removed value [org.mybatis.spring.SqlSessionHolder@98cbf7] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@869470]
from thread [main]
2012-04-25 09:57:28,661 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Transaction synchronization closing SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@173a64a]
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@1d2b8e] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@1efa490]
bound to thread [main]
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Clearing transaction synchronization
2012-04-25 09:57:28,661 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Removed value
[org.springframework.jdbc.datasource.ConnectionHolder@1d2b8e] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@1efa490]
from thread [main]
2012-04-25 09:57:28,661 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Releasing JDBC Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@8814509 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
after transaction
2012-04-25 09:57:28,661 DEBUG
[org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC
Connection to DataSource
2012-04-25 09:57:28,661 INFO
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Rolled back transaction after test execution for test context
[[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientMapperIntegrationTest,
testException = java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException,
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]]
2012-04-25 09:57:28,661 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test method: context [[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientMapperIntegrationTest,
testException = java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException,
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
class dirties context [false], class mode [null], method dirties
context [false].
2012-04-25 09:57:28,661 TRACE
[org.springframework.test.context.TestContextManager] -
afterTestClass(): class [class
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest]
2012-04-25 09:57:28,661 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test class: context [[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance = [null],
testMethod = [null], testException = [null],
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
dirtiesContext [false].
2012-04-25 09:57:28,676 INFO
[org.springframework.context.support.GenericApplicationContext] -
Closing
org.springframework.context.support.GenericApplicationContext@b5dac4:
startup date [Wed Apr 25 09:57:27 EEST 2012]; root of context
hierarchy

And here is the same using SqlSessionTemplate and a DAO:

2012-04-25 09:58:45,727 INFO
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Began transaction (1): transaction manager
[org.springframework.jdbc.datasource.DataSourceTransactionManager@2c7ac5];
rollback [true]
2012-04-25 09:58:45,727 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Creating a new SqlSession
2012-04-25 09:58:45,727 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Registering transaction synchronization for SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,727 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Bound value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
to thread [main]
2012-04-25 09:58:45,758 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@162e703] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@18c6982]
bound to thread [main]
2012-04-25 09:58:45,758 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@162e703] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@18c6982]
bound to thread [main]
2012-04-25 09:58:45,758 DEBUG
[org.mybatis.spring.transaction.SpringManagedTransaction] - JDBC
Connection [org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID
= 193), (SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID =
null) ] will be managed by Spring
2012-04-25 09:58:45,758 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:58:45,758 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ==>  Preparing: select
EMP_ID, EMP_MODIFIED_TIME, EMP_FIRST_NAME, EMP_LAST_NAME, EMP_PHONE,
EMP_EMAIL from T_TIMEBASED_EMPLOYEES where EMP_ID=?
2012-04-25 09:58:45,805 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ==> Parameters: 1(Long)
2012-04-25 09:58:45,821 TRACE
[TimeBasedEmployee.getTimeBasedEmployeeById] - <==    Columns: EMP_ID,
EMP_MODIFIED_TIME, EMP_FIRST_NAME, EMP_LAST_NAME, EMP_PHONE, EMP_EMAIL
2012-04-25 09:58:45,821 TRACE
[TimeBasedEmployee.getTimeBasedEmployeeById] - <==        Row: 1,
2010-03-01 00:00:00.123, Mikko, Mallikas, 010-1234567,
[hidden email]
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390] from
current transaction
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,821 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,821 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390] from
current transaction
2012-04-25 09:58:45,821 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:58:45,821 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ==>  Preparing: update
T_TIMEBASED_EMPLOYEES set EMP_MODIFIED_TIME = CURRENT_TIMESTAMP,
EMP_FIRST_NAME = ?, EMP_LAST_NAME = ?, EMP_PHONE = ?, EMP_EMAIL = ?
where EMP_ID = ? and EMP_MODIFIED_TIME = ?
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ==> Parameters:
Mikko(String), Åberg(String), 010-1234567(String),
[hidden email](String), 1(Long), 2010-03-01
00:00:00.123(Timestamp)
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390] from
current transaction
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ==>  Preparing: select
EMP_ID, EMP_MODIFIED_TIME, EMP_FIRST_NAME, EMP_LAST_NAME, EMP_PHONE,
EMP_EMAIL from T_TIMEBASED_EMPLOYEES where EMP_ID=?
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.getTimeBasedEmployeeById] - ==> Parameters: 1(Long)
2012-04-25 09:58:45,836 TRACE
[TimeBasedEmployee.getTimeBasedEmployeeById] - <==    Columns: EMP_ID,
EMP_MODIFIED_TIME, EMP_FIRST_NAME, EMP_LAST_NAME, EMP_PHONE, EMP_EMAIL
2012-04-25 09:58:45,836 TRACE
[TimeBasedEmployee.getTimeBasedEmployeeById] - <==        Row: 1,
2012-04-25 09:58:45.836, Mikko, Åberg, 010-1234567, [hidden email]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Fetched SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390] from
current transaction
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ooo Using Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ==>  Preparing: update
T_TIMEBASED_EMPLOYEES set EMP_MODIFIED_TIME = CURRENT_TIMESTAMP,
EMP_FIRST_NAME = ?, EMP_LAST_NAME = ?, EMP_PHONE = ?, EMP_EMAIL = ?
where EMP_ID = ? and EMP_MODIFIED_TIME = ?
2012-04-25 09:58:45,836 DEBUG
[TimeBasedEmployee.updateTimeBasedEmployee] - ==> Parameters:
Mikko(String), Åberg(String), 010-1234567(String),
[hidden email](String), 1(Long), 2010-03-01
00:00:00.123(Timestamp)
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
bound to thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Releasing transactional SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,836 TRACE
[org.springframework.test.context.TestContextManager] -
afterTestMethod(): instance
[my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa],
method [public void
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest.testTimeBasedOptimisticLocking()],
exception [null]
2012-04-25 09:58:45,836 DEBUG
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- No method-level @Rollback override: using default rollback [true]
for test context [[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientRepositoryIntegrationTest,
testException = [null], mergedContextConfiguration =
[MergedContextConfiguration@6ac461 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]]
2012-04-25 09:58:45,836 TRACE
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Ending transaction for test context [[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientRepositoryIntegrationTest,
testException = [null], mergedContextConfiguration =
[MergedContextConfiguration@6ac461 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]];
transaction manager
[org.springframework.transaction.support.DefaultTransactionStatus@3fc47c];
rollback [true]
2012-04-25 09:58:45,836 TRACE
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Triggering beforeCompletion synchronization
2012-04-25 09:58:45,836 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Initiating transaction rollback
2012-04-25 09:58:45,836 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Rolling back JDBC transaction on Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
2012-04-25 09:58:45,836 TRACE
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Triggering afterCompletion synchronization
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Removed value [org.mybatis.spring.SqlSessionHolder@fa706d] for key
[org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@1169fb2]
from thread [main]
2012-04-25 09:58:45,836 DEBUG [org.mybatis.spring.SqlSessionUtils] -
Transaction synchronization closing SqlSession
[org.apache.ibatis.session.defaults.DefaultSqlSession@60e390]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Retrieved value
[org.springframework.jdbc.datasource.ConnectionHolder@162e703] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@18c6982]
bound to thread [main]
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Clearing transaction synchronization
2012-04-25 09:58:45,836 TRACE
[org.springframework.transaction.support.TransactionSynchronizationManager]
- Removed value
[org.springframework.jdbc.datasource.ConnectionHolder@162e703] for key
[org.springframework.jdbc.datasource.SimpleDriverDataSource@18c6982]
from thread [main]
2012-04-25 09:58:45,836 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Releasing JDBC Connection
[org.apache.derby.impl.jdbc.EmbedConnection40@2153655 (XID = 193),
(SESSIONID = 5), (DATABASE = memory:dataSource), (DRDAID = null) ]
after transaction
2012-04-25 09:58:45,852 DEBUG
[org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC
Connection to DataSource
2012-04-25 09:58:45,852 INFO
[org.springframework.test.context.transaction.TransactionalTestExecutionListener]
- Rolled back transaction after test execution for test context
[[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientRepositoryIntegrationTest,
testException = [null], mergedContextConfiguration =
[MergedContextConfiguration@6ac461 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]]
2012-04-25 09:58:45,852 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test method: context [[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientRepositoryIntegrationTest,
testException = [null], mergedContextConfiguration =
[MergedContextConfiguration@6ac461 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
class dirties context [false], class mode [null], method dirties
context [false].
2012-04-25 09:58:45,852 TRACE
[org.springframework.test.context.TestContextManager] -
afterTestClass(): class [class
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest]
2012-04-25 09:58:45,852 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test class: context [[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance = [null],
testMethod = [null], testException = [null],
mergedContextConfiguration = [MergedContextConfiguration@6ac461
testClass = AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
dirtiesContext [false].
2012-04-25 09:58:45,852 INFO
[org.springframework.context.support.GenericApplicationContext] -
Closing
org.springframework.context.support.GenericApplicationContext@17e4ca:
startup date [Wed Apr 25 09:58:44 EEST 2012]; root of context
hierarchy

Note, the update-method in SqlSessionTempalte-approach explicitly
loads the updated object after the update as is evident above, the
MapperFactoryBean does not. However, this is not the culprit as the
result is the same even if I explicitly load the object after the
update with the Mapper-approach.

Towards the end of the log output you can see the difference in
behaviour:

2012-04-25 09:57:28,661 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test method: context [[TestContext@b23210 testClass =
AbstractSqlMapClientMapperIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientMapperIntegrationTest@157c2bd,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientMapperIntegrationTest,
testException = java.lang.AssertionError: Expected exception:
org.springframework.dao.OptimisticLockingFailureException,
mergedContextConfiguration = [MergedContextConfiguration@f4f44a
testClass = AbstractSqlMapClientMapperIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
class dirties context [false], class mode [null], method dirties
context [false].

2012-04-25 09:58:45,852 DEBUG
[org.springframework.test.context.support.DirtiesContextTestExecutionListener]
- After test method: context [[TestContext@4c4975 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, testInstance =
my.sample.persistence.ibatis.AbstractSqlMapClientRepositoryIntegrationTest@1d256fa,
testMethod =
testTimeBasedOptimisticLocking@AbstractSqlMapClientRepositoryIntegrationTest,
testException = [null], mergedContextConfiguration =
[MergedContextConfiguration@6ac461 testClass =
AbstractSqlMapClientRepositoryIntegrationTest, locations =
'{classpath:test-config.xml}', classes = '{}', activeProfiles = '{}',
contextLoader =
'org.springframework.test.context.support.DelegatingSmartContextLoader']]],
class dirties context [false], class mode [null], method dirties
context [false].

-Kari

[Eduardo Macarron]

Logs look fine. But.... where is that
OptimisticLockingFailureException being thrown from?

[Kari Pulkka]

Not sure if I understand your question but the second update should
fail, so I guess that Spring raises the exception after it gets the
sql error code. This is the correct and expected result and works with
SqlSessionTemplate but not with MapperFactoryBean.

[Eduardo Macarron]

Could you post the stacktrace?

[Keith Wong]

The test case will not throw the OptimisticLockingFailureException.
MyBatis will not throw exceptions on update count is zero.  I handle
this problem by creating a MyBatis plugin and throw an exception when
the update count is zero.  No need to update the mapper code.

[Eduardo Macarron]

Hi Keith. Thanks for you help!

What I do not understand is who is throwing that
OptimisticLockingFailureException in the case that works for Kari.

[Kari Pulkka]

Keith, could you give a sample of the plugin you mentioned? Thanks in
advance!

-Kari

[Keith Wong]

Here is an over-simplified example.  Implements the isOptimistic
method for your needs or all update statements will be covered.  Have
fun.

@Intercepts(
    @Signature(type=Executor.class, method="update",
args={MappedStatement.class, Object.class})
)
public class OptimisticAccess implements Interceptor {

    public Object intercept(Invocation invocation) throws Throwable {
        Object[] args = invocation.getArgs();
        MappedStatement ms = (MappedStatement)args[0];
        Object param = args[1];

        SqlCommandType type = ms.getSqlCommandType();
        boolean isOptimistic = isOptimistic(type, param);

        int count = (Integer)invocation.proceed();

        if (isOptimistic && count == 0) {
            throw new PluginException(new SQLDataException(new
OptimisticLockException(String.format(
                    "Optimistic Locking Failed: Entity %s of type [%s]
executing [%s]",
                    param, param.getClass().getName(), ms.getId()))));
        }
        return count;
    }

    private static boolean isOptimistic(SqlCommandType type, Object
param) {
        return (type == SqlCommandType.INSERT || type ==
SqlCommandType.UPDATE || type == SqlCommandType.DELETE);
    }

    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }
}