Atomikos Forum

We are using Atomikos 3.6.5 + Hibernate 3.3.2+ JBoss cache2 in our product. I found this strange error message from "tm.out":

"com.atomikos.icatch.SysException: Error in prepare: null"

The error message in "tm.out" didn't anything what might cause the error. This problem didn't always happen. Other transactions seems fine, only this transaction sometime failed. The problem happened with both MySql and Oracle. So it seems not a database specific problem.

Here is the snapshot of "tm.out":

10-08-23 22:00:00,927 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@292cb2: calling prepareStatement...
10-08-23 22:00:00,927 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@292cb2: prepareStatement returning com.mysql.jdbc.jdbc2.optional.JDBC4PreparedStatementWrapper@f74f5f
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction()  returning instance with id 127.0.0.1.tm0282900122
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] commit() done (by application) of transaction 127.0.0.1.tm0282900122
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Coordinator 127.0.0.1.tm0282900122 entering state: PREPARING
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Coordinator 127.0.0.1.tm0282900122 entered state: PREPARING
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@58fe78
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] ThreadFactory: creating new thread: Atomikos:33
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@15804cd
10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] ThreadFactory: creating new thread: Atomikos:34
10-08-23 22:00:00,930 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Error in prepare: null
com.atomikos.icatch.SysException: Error in prepare: null
        at com.atomikos.icatch.imp.ActiveStateHandler.prepare(ActiveStateHandler.java:287)
        at com.atomikos.icatch.imp.CoordinatorImp.prepare(CoordinatorImp.java:803)
        at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1124)
        at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
        at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:298)
        at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:612)
        at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168)
        at com.resolve.persistence.util.HibernateUtil.commitTransaction(HibernateUtil.java:480)
        at com.resolve.rscontrol.ProcessExecution.abortProcess(ProcessExecution.java:549)
        at com.resolve.rscontrol.MAction.abortProcess(MAction.java:364)
        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:597)
        at com.resolve.thread.ExecutorTask.execute(ExecutorTask.java:285)
        at com.resolve.thread.ExecutorTask.call(ExecutorTask.java:127)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
10-08-23 22:00:00,934 [Atomikos:34] XAResource.end ( 3132372E302E302E312E746D30323832393030313232:3132372E302E302E312E746D32343539 , XAResource.TMSUCCESS ) on resource F2D11751C0ED4A80734787689719BA80 represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@1712a80
10-08-23 22:00:00,938 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning NULL!
10-08-23 22:00:00,938 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning NULL!


Just wondering if anybody knows anything about this strange error?Any help is greatly appreciated!

Yu

Hi,

Can you post some context on what your app is supposed to do?

Thanks

Our product is a runbook automation system:http://resolve-systems.com/index.html.  Multiple members are running in a cluster which all access a backend database for storage. Atomikos is used as a JTA manager to manage transactions at each cluster member, and also coordinate distributed cache managed by JBoss.

Atomikos works fine when workload is light. But under stress tests, where lots of tasks are running in parallel and database is heavilly contented, we started to see this error manage after running about 10-15 minutes. Then more and more transactions failed with this error message which we don't have a clue at all. No other exceptions were found in our system.

Here is "jta.properities" file:
com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.automatic_resource_registration=true
com.atomikos.icatch.console_log_level=DEBUG
com.atomikos.icatch.serial_jta_transactions=true
com.atomikos.icatch.enable_logging=true
com.atomikos.icatch.max_timeout=180000
com.atomikos.icatch.default_jta_timeout=180000
com.atomikos.icatch.log_base_dir=/opt/resolve/rscontrol/log
com.atomikos.icatch.output_dir=/opt/resolve/rscontrol/log

Any hint for debugging this error?

Thanks,
Yu

Hi,

We're following this thread to improve our product, thanks. In the meantime: did you try increasing the minPoolSize?

HTH

We found the cause of the problem. It was a bug in our code. It seems Atomikos transaction manager tried to start a new thread when started 2PC commit procedure. But the original pool thread sometimes might be interrupted (canceled) because of race conditions in our code. So basically commit process was interrupted by thread death in our code. Atomikos code actually caught InterruptedException when this happened, but failed to print out meaningful error message to log.

OK thanks

I will create an issue to fix this logging then...

Cheers