Atomikos Forum

Hi,

I'm evaluating Atomikos Transcation Essentials (v. 3.5.6) with MySQL 5.1 and programmed a little JUnit-Test to check its functionality and was happy how easy it can be set up.

However, the test involving rollback fails (records inserted during the TX which is then rolled back are in the database after the test completes) and I have no idea why.

the code of the test is:

userTransaction.begin();
connection = dataSource.getConnection();
// inserts a record with jdbc, values do not matter
insertRecord(connection, 2, "value 2");
userTransaction.rollback();

assertEquals("Wrong number of records after rollback", 0,
// returns result from select count(*) query on the table
countRecords(connection));
 
Datasource and UserTransaction are set up as follows:

dataSource = new AtomikosNonXADataSourceBean();
dataSource.setDriverClassName("com.mysql.jdbc.Driver");
dataSource.setUser(System.getProperty("db.user", "xyz"));
dataSource.setPassword(System.getProperty("db.password","xyz"));
dataSource.setUrl(System.getProperty("db.url","jdbc:mysql://localhost/test"));
dataSource.setUniqueResourceName("Test Datasource");
dataSource.setMaxPoolSize(5);
userTransaction = new UserTransactionImp();

And the table is cleared in the setUp method which I verified.

The TM configuration is:
com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.console_file_name = atomikos-console.out
com.atomikos.icatch.console_file_limit=-1
com.atomikos.icatch.output_dir = ./log
com.atomikos.icatch.log_base_dir = ./log
com.atomikos.icatch.max_actives = 50
com.atomikos.icatch.default_jta_timeout = 10000
com.atomikos.icatch.max_timeout = 300000
com.atomikos.icatch.tm_unique_name = Test TM
com.atomikos.icatch.serial_jta_transactions=false
com.atomikos.icatch.console_log_level=DEBUG

The console output for this run is:

09-08-01 17:28:35,818 [main] cannot load SLF4J, skipping this console
java.lang.ClassNotFoundException: org.slf4j.Logger
    at java.net.URLClassLoader$1.run(URLClassLoader.java:200)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:316)
    at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:280)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
    at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:374)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:164)
    at com.atomikos.icatch.standalone.UserTransactionServiceImp.createDefault(UserTransactionServiceImp.java:175)
    at com.atomikos.icatch.standalone.UserTransactionServiceImp.init(UserTransactionServiceImp.java:281)
    at com.atomikos.icatch.config.UserTransactionServiceImp.init(UserTransactionServiceImp.java:373)
    at com.atomikos.icatch.jta.UserTransactionImp.checkSetup(UserTransactionImp.java:138)
    at com.atomikos.icatch.jta.UserTransactionImp.begin(UserTransactionImp.java:153)
    at de.lesspain.playground.atomikos.test.AtomikosTest.testBasicRollback(AtomikosTest.java:77)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at junit.framework.TestCase.runTest(TestCase.java:164)
    at junit.framework.TestCase.runBare(TestCase.java:130)
    at junit.framework.TestResult$1.protect(TestResult.java:106)
    at junit.framework.TestResult.runProtected(TestResult.java:124)
    at junit.framework.TestResult.run(TestResult.java:109)
    at junit.framework.TestCase.run(TestCase.java:120)
    at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
    at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
09-08-01 17:28:35,841 [main] Starting read of logfile /Users/krueger/eclipse-workspaces/lp/test/de.lesspain.playground.atomikos.test/./log/tmlog7.log
09-08-01 17:28:35,844 [main] Done read of logfile
09-08-01 17:28:35,848 [main] USING core version: 3.5.6
09-08-01 17:28:35,848 [main] USING com.atomikos.icatch.console_file_name = atomikos-console.out
09-08-01 17:28:35,848 [main] USING com.atomikos.icatch.console_file_count = 1
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.automatic_resource_registration = true
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.client_demarcation = false
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.threaded_2pc = true
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.serial_jta_transactions = false
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.log_base_dir = ./log
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.console_log_level = DEBUG
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.max_actives = 50
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.checkpoint_interval = 500
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.enable_logging = true
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.output_dir = ./log
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.log_base_name = tmlog
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.console_file_limit = -1
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.max_timeout = 300000
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.tm_unique_name = Test TM
09-08-01 17:28:35,849 [main] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
09-08-01 17:28:35,849 [main] USING java.naming.provider.url = rmi://localhost:1099
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
09-08-01 17:28:35,849 [main] USING com.atomikos.icatch.force_shutdown_on_vm_exit = false
09-08-01 17:28:35,850 [main] USING com.atomikos.icatch.default_jta_timeout = 10000
09-08-01 17:28:35,850 [main] getCompositeTransaction() returning NULL!
09-08-01 17:28:35,864 [main] Coordinator Test TM0000100009 entering state: ACTIVE
09-08-01 17:28:35,865 [main] Coordinator Test TM0000100009 entered state: ACTIVE
09-08-01 17:28:35,865 [main] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@d978ea
09-08-01 17:28:35,865 [main] ThreadFactory: creating new thread: Atomikos:1
09-08-01 17:28:35,866 [main] Creating composite transaction: Test TM0000100009
09-08-01 17:28:35,870 [main] createCompositeTransaction ( 10000 ): created new ROOT transaction with id Test TM0000100009
09-08-01 17:28:35,874 [main] AtomikosNonXADataSourceBean 'Test Datasource': getConnection ( null )...
09-08-01 17:28:35,874 [main] AtomikosNonXADataSourceBean 'Test Datasource': init...
09-08-01 17:28:35,874 [main] AtomikosNonXADataSourceBean 'Test Datasource': getConnection ( null )...
09-08-01 17:28:35,874 [main] AtomikosNonXADataSourceBean 'Test Datasource': init...
09-08-01 17:28:35,874 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,874 [main] atomikos connection pool 'Test Datasource': current size: 1/1
09-08-01 17:28:35,874 [main] AtomikosNonXAPooledConnection: updating last time acquired
09-08-01 17:28:35,874 [main] AtomikosNonXAPooledConnection: no test query, skipping test
09-08-01 17:28:35,874 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,874 [main] AtomikosNonXAPooledConnection: creating connection proxy...
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling toString on vendor connection...
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: toString returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] AtomikosNonXAPooledConnection: returning proxy com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] atomikos connection pool 'Test Datasource': got connection from pool, new size: 1/1
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling toString on vendor connection...
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: toString returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] AtomikosNonXADataSourceBean 'Test Datasource': returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling toString on vendor connection...
09-08-01 17:28:35,875 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: toString returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] AtomikosNonXADataSourceBean 'Test Datasource': returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,875 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,876 [main] Coordinator Test TM0000100009 entering state: ACTIVE
09-08-01 17:28:35,876 [main] Coordinator Test TM0000100009 entered state: ACTIVE
09-08-01 17:28:35,876 [main] addParticipant ( com.atomikos.jdbc.nonxa.AtomikosNonXAParticipant@67c6fd ) for transaction Test TM0000100009
09-08-01 17:28:35,877 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling createStatement on vendor connection...
09-08-01 17:28:35,877 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: createStatement returning com.mysql.jdbc.StatementImpl@39452f
09-08-01 17:28:35,877 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: getAutoCommit()...
09-08-01 17:28:35,877 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: getAutoCommit() returning false.
09-08-01 17:28:35,878 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,878 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling prepareStatement on vendor connection...
09-08-01 17:28:35,887 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: prepareStatement returning com.mysql.jdbc.PreparedStatement@bd669d: insert into test (id, value) values (** NOT SPECIFIED **, ** NOT SPECIFIED **)
09-08-01 17:28:35,888 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,888 [main] getCompositeTransaction()  returning instance with id Test TM0000100009
09-08-01 17:28:35,889 [main] Coordinator Test TM0000100009 entering state: ABORTING
09-08-01 17:28:35,889 [main] Coordinator Test TM0000100009 entered state: ABORTING
09-08-01 17:28:35,891 [main] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@4ec59
09-08-01 17:28:35,891 [main] ThreadFactory: creating new thread: Atomikos:2
09-08-01 17:28:35,891 [Atomikos:2] Forcing close of pending statement: com.mysql.jdbc.StatementImpl@39452f
09-08-01 17:28:35,891 [Atomikos:2] Forcing close of pending statement: com.mysql.jdbc.PreparedStatement@bd669d: statement has been closed, no further internal information available
09-08-01 17:28:35,891 [Atomikos:2] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: transaction aborting - pessimistically closing all pending statements to avoid autoCommit after timeout
09-08-01 17:28:35,891 [Atomikos:2] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: rolling back on connection...
09-08-01 17:28:35,891 [Atomikos:2] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: resetting autoCommit to true
09-08-01 17:28:35,892 [Atomikos:2] ThreadLocalConnection: not reusable yet
09-08-01 17:28:35,892 [main] Coordinator Test TM0000100009 entering state: TERMINATED
09-08-01 17:28:35,892 [main] Coordinator Test TM0000100009 : stopping timer...
09-08-01 17:28:35,892 [main] Coordinator Test TM0000100009 : disposing statehandler TERMINATED...
09-08-01 17:28:35,892 [main] Coordinator Test TM0000100009 : disposed.
09-08-01 17:28:35,894 [main] Coordinator Test TM0000100009 entered state: TERMINATED
09-08-01 17:28:35,894 [main] rollback() done of transaction Test TM0000100009
09-08-01 17:28:35,894 [main] getCompositeTransaction() returning NULL!
09-08-01 17:28:35,894 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling createStatement on vendor connection...
09-08-01 17:28:35,895 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: createStatement returning com.mysql.jdbc.StatementImpl@285d14
09-08-01 17:28:35,895 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: calling toString on vendor connection...
09-08-01 17:28:35,895 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: toString returning com.mysql.jdbc.ConnectionImpl@e555bd
09-08-01 17:28:35,895 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: close...
09-08-01 17:28:35,896 [main] ThreadLocalConnection: detected reusability
09-08-01 17:28:35,896 [main] AtomikosNonXAPooledConnection: notifying listener: atomikos connection pool 'Test Datasource'
09-08-01 17:28:35,896 [main] atomikos connection pool 'Test Datasource': connection AtomikosNonXAPooledConnection became available, notifying potentially waiting threads
09-08-01 17:28:35,896 [main] atomikos non-xa connection proxy for com.mysql.jdbc.ConnectionImpl@e555bd: close done.
09-08-01 17:28:35,896 [main] AtomikosNonXADataSourceBean 'Test Datasource': close...
09-08-01 17:28:35,896 [main] atomikos connection pool 'Test Datasource': destroying pool...
09-08-01 17:28:35,896 [main] AtomikosNonXAPooledConnection: destroying...
09-08-01 17:28:35,897 [main] atomikos connection pool 'Test Datasource': pool destroyed.
09-08-01 17:28:35,897 [main] AtomikosNonXADataSourceBean 'Test Datasource': close done.

It must be an obvious mistake on my side. However, I've been staring at this, verifying everything several times and I am running out of ideas.

Thanks,

Robert

Please forget it! I ran the test on a MySQL database with MyIsam Storage engine as default, i.e. without TX support.

My mistake. Works now with InnoDB and please excuse the noise!