2PC in Cluster with Informix

[j_ri]

Hello,

cuurently we have problems to switch to JBoss EAP 4.3.0 GA with JBossTransactions4.3.0GA configured in JTS mode.

Unfortunately we discovered that a distributed Transaction spanning EJBs on two cluster nodes is not working when using INFORMIX (9.40 Driver JDBC.3.00.JC1) Datasources. Under Oracle everything is working fine.

Do you have any experience with JBossTransactions 4.3.0 and Informix Databases?
Did you know a solution how to get this to work?

Thanks
Jochen

P.S.: I just did another test. When using one Oracle and one Informix datasource it's still working. The problem only occurs if both cluster nodes access Informix.
P.P.S.: I also tried the new Driver JDBC.3.50.JC1 now...same result

[jhalliday]

In what way is it not working? Wrong result? Exception?

[j_ri]

the second cluster-node can't read the data which was written to the database by the first cluster node. there is an exceptions (in the second cluster-node) which means that the data is locked by the first cluster-node, so that the second can't read the data.

So it seems that trhze two nodes don't use the same transaction.

here is the stacktrace:

2008-07-28 13:34:09,304 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackException in method: public abstract java.lang.String de.lbank.xatestnode2.ejb.XATestNode2Facade.testInnerTransactionJdbcOk(int,java.sql.Timestamp,boolean) throws java.rmi.RemoteException, causedBy:
de.lbank.framework.exception.FrameworkException: Could not do a physical-order read to fetch next row.
 at de.lbank.framework.exception.DefaultExceptionHandler.runtimeException(DefaultExceptionHandler.java:222)
 at de.lbank.xatestnode2.ejb.XATestNode2FacadeBean.testInnerTransactionJdbcOk(XATestNode2FacadeBean.java:116)
 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 org.jboss.invocation.Invocation.performCall(Invocation.java:359)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:237)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:158)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:169)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
 at org.jboss.ejb.plugins.CleanShutdownInterceptor.invoke(CleanShutdownInterceptor.java:278)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:648)
 at org.jboss.ejb.Container.invoke(Container.java:960)
 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 org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
 at org.jboss.invocation.unified.server.UnifiedInvokerHA.invoke(UnifiedInvokerHA.java:148)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:795)
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:573)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:387)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:166)
Caused by: java.sql.SQLException: Could not do a physical-order read to fetch next row.
 at com.informix.jdbc.IfxSqli.a(IfxSqli.java:3280)
 at com.informix.jdbc.IfxSqli.E(IfxSqli.java:3593)
 at com.informix.jdbc.IfxSqli.dispatchMsg(IfxSqli.java:2405)
 at com.informix.jdbcx.IfxXASqli.receiveMessage(IfxXASqli.java:120)
 at com.informix.jdbc.IfxSqli.a(IfxSqli.java:1591)
 at com.informix.jdbc.IfxSqli.executeStatementQuery(IfxSqli.java:1529)
 at com.informix.jdbc.IfxSqli.executeStatementQuery(IfxSqli.java:1460)
 at com.informix.jdbc.IfxResultSet.a(IfxResultSet.java:206)
 at com.informix.jdbc.IfxStatement.executeQueryImpl(IfxStatement.java:1228)
 at com.informix.jdbc.IfxPreparedStatement.executeQuery(IfxPreparedStatement.java:371)
 at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:236)
 at de.lbank.xatestnode2.ejb.XATestNode2FacadeBean.lesenDerAuesserenDaten(XATestNode2FacadeBean.java:184)
 at de.lbank.xatestnode2.ejb.XATestNode2FacadeBean.testInnerTransactionJdbcOk(XATestNode2FacadeBean.java:110)
 ... 32 more
Caused by: java.sql.SQLException: ISAM error: Lock Timeout Expired
 at com.informix.util.IfxErrMsg.getSQLException(IfxErrMsg.java:400)
 at com.informix.jdbc.IfxSqli.E(IfxSqli.java:3598)
 ... 43 more
2008-07-28 13:34:09,429 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_43] - Transaction -69b8f474:843:488d97d1:103 marked as rollback only. Will abort.
2008-07-28 13:34:09,460 INFO [org.jboss.resource.connectionmanager.CachedConnectionManager] Closing a connection for you. Please close them yourself: org.jboss.resource.adapter.jdbc.WrappedConnection@1ed2f0
java.lang.Throwable: STACKTRACE
 at org.jboss.resource.connectionmanager.CachedConnectionManager.registerConnection(CachedConnectionManager.java:290)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:417)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)

[jhalliday]

> So it seems that trhze two nodes don't use the same transaction.

That's not necessarily the case. In XA transactions, each node would have its own branch. Resource manager's may use either loose coupling or tight coupling of transaction branches. This basically determines if branches share locks or not i.e. if two branches can see one another's changes or if they block one another. Odds are Oracle is using tight coupling (lock sharing) by default, which sounds like what you expect/need.

http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28424/adfns_xa.htm#i1007088

My guess is Informix is using loose coupling.

[j_ri]

thanks for the hint.

I'll try to find out if there's a possibility to configure tight coupling on Informix...or if it's a bug in the jdbc driver (I found a web page on which the problem is described for Informix used by the Microsoft Transaction Server..there the problem is solved)
http://www-306.ibm.com/software/data/informix/pubs/library/notes/relnotes/9.40.xc7/ids_win_release_notes_9.40.html

[j_ri]

your hint solved my problem;-)

there's a parameter for informix datasources which enforces the tight coupling. just add the following to the XA-datasource definition:

<xa-datasource-property name="IfxIFX_XASPEC">y</xa-datasource-property>

thanks

[j_ri]

we have one more problem.

if the server in the obove mentioned configuration is running idle for a while, the following warnings occur in der server.log:

2008-07-30 11:36:49,655 WARN [com.arjuna.ats.jts.logging.loggerI18N] [com.arjuna.ats.internal.jts.cwcommit] Failed to mark transaction as rollback only:
org.omg.CosTransactions.Unavailable: IDL:omg.org/CosTransactions/Unavailable:1.0
 at com.arjuna.ats.internal.jts.ControlWrapper.rollback_only(ControlWrapper.java:344)
 at com.arjuna.ats.internal.jts.ControlWrapper.preventCommit(ControlWrapper.java:168)
 at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:717)
 at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:91)
2008-07-30 11:36:50,354 WARN [com.arjuna.ats.jts.logging.loggerI18N] [com.arjuna.ats.internal.jts.cwcommit] Failed to mark transaction as rollback only:
org.omg.CosTransactions.Unavailable: IDL:omg.org/CosTransactions/Unavailable:1.0
 at com.arjuna.ats.internal.jts.ControlWrapper.rollback_only(ControlWrapper.java:344)
 at com.arjuna.ats.internal.jts.ControlWrapper.preventCommit(ControlWrapper.java:168)
 at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:717)
 at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:91)
2008-07-30 11:36:50,522 WARN [com.arjuna.ats.jts.logging.loggerI18N] [com.arjuna.ats.internal.jts.cwcommit] Failed to mark transaction as rollback only:
org.omg.CosTransactions.Unavailable: IDL:omg.org/CosTransactions/Unavailable:1.0
 at com.arjuna.ats.internal.jts.ControlWrapper.rollback_only(ControlWrapper.java:344)
 at com.arjuna.ats.internal.jts.ControlWrapper.preventCommit(ControlWrapper.java:168)
 at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:717)
 at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:91)
2008-07-30 11:36:51,194 WARN [com.arjuna.ats.jts.logging.loggerI18N] [com.arjuna.ats.internal.jts.cwcommit] Failed to mark transaction as rollback only:
org.omg.CosTransactions.Unavailable: IDL:omg.org/CosTransactions/Unavailable:1.0
 at com.arjuna.ats.internal.jts.ControlWrapper.rollback_only(ControlWrapper.java:344)
 at com.arjuna.ats.internal.jts.ControlWrapper.preventCommit(ControlWrapper.java:168)
 at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:717)
 at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:91)

any ideas where they come from?

thanks

[adinn]

Well, this is happening when the transaction reaper thread decides a TX has timed out. TXs are entered into its table at create time and removed when the TX exits. If a TX continues beyond its timeout the reaper wakes up and forces it to rollback.

Now in your case the reaper gets a null pointer exception when it tries to cancel the TX, apparently because the Corba remote handle is invalid (the Unavailable exception gets thrown when this NPE is caught). This might have happened for a variety of reasons. In particular, it may be because the TX has completed but failed to remove itself from the reaper's table. It's not possible to say without more information.

If you switch on TX debug level logging and rerun you should obttain the relevant info to diagnose this. First thing to look for is a reaper printout of the TX id just before it tries to do the cancel and gets an NPE/Unavailable exception. If you can trace back through the log and check the progress of the TX with this id you should see when it started and whether it was prepared, committed or aborted.

I'd be very interested to see any relevant log output.

[j_ri]

how do I have to configure looging so that you can see the TX logging.

I configured categories for "org.jboss.tm" "com.arjuna" and "org.hibernate" in DEBUG mode, but I can't see calls to commit, prepare or rollback;-(

[j_ri]

the problem got worse...and hence it has nothing to do with the original topic of this thrfed I created a new one:
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4170236#4170236