JBoss 7.1.1, Hibernate 3.6.10, XA Datasources
heldwein Jan 31, 2013 6:36 AMI have an issue here with JBoss 7.1.1, Hibernate 3.6.10 and XA Datasources.
The applications works perfectly as it should with a MySQL database but is causing problems if we switch to Oracle RAC.
Scenario:
Entity Person consists of two attributes: lastname and id, where the latter one is using a generic generator:
Entity
@Entity
public class Person implements Serializable {
@Id
@Column(name="PERSONKEY")
@GeneratedValue(generator="mygen")
@GenericGenerator(name="mygen", strategy="de.protosoft.jb7hibernate.custom.NumberGenerator")
private String id;
private String lastname;
... setters/getters left out here.
The NumberGenerator is very simple:
public class NumberGenerator implements IdentifierGenerator {
public Serializable generate(SessionImplementor session, Object object) throws HibernateException {
Random generator = new Random( new Date().getTime() );
long id = generator.nextLong();
return "CH"+id;
}
}
My persistence.xml:
<?xml version="1.0" encoding="UTF-8"?>
<persistence version="2.0" xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">
<persistence-unit name="jb7hibernate" transaction-type="JTA">
<jta-data-source>java:jboss/datasources/MyXADS</jta-data-source>
<class>de.protosoft.jb7hibernate.entity.Person</class>
<properties>
<property name="hibernate.dialect" value="org.hibernate.dialect.MySQLDialect" />
<property name="hibernate.hbm2ddl.auto" value="create-drop" />
<property name="hibernate.show_sql" value="true" />
<property name="hibernate.format_sql" value="true" />
<property name="hibernate.connection.characterEncoding" value="UTF-8" />
<property name="jboss.as.jpa.providerModule" value="org.hibernate:3" />
</properties>
</persistence-unit>
</persistence>
I have changed the provider to Hibernate 3.6.10, and installed the libraries into the module org.hibernate, slot 3:
The module.xml
It looks like:
<module xmlns="urn:jboss:module:1.0" name="org.hibernate" slot="3">
<resources>
<resource-root path="hibernate3.jar"/>
<resource-root path="javassist-3.12.0.GA.jar"/>
<resource-root path="antlr-2.7.6.jar"/>
<resource-root path="commons-collections-3.1.jar"/>
</resources>
<dependencies>
<module name="org.dom4j"/>
<module name="org.jboss.as.jpa.hibernate" slot="3"/>
<module name="asm.asm"/>
<module name="javax.api"/>
<module name="javax.persistence.api"/>
<module name="javax.transaction.api"/>
<module name="javax.validation.api"/>
<module name="org.infinispan"/>
<module name="org.javassist"/>
<module name="org.slf4j"/>
</dependencies>
</module>
During startup, the following message appears in the logfile, therefore I assume, the installation of Hibernate 3.6.10 should be ok:
10:38:15,021 INFO [org.hibernate.cfg.Environment] (MSC service thread 1-8) Hibernate 3.6.10.Final
Bean
A stateless bean is responsible to store the person in the database:
(TransactionAttribute would be not required for this test case, but is mandatory in the real project)
@Stateless
@Remote(PersonData.class)
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
public class PersonDataBean implements PersonData {
@PersistenceContext
private EntityManager em;
protected Session getSession() {
return (Session)em.getDelegate();
}
public void persist(Person person) {
Session session = getSession();
session.saveOrUpdate(person);
session.flush();
}
}
Client
The persist method is called by a standalone client outside of JBoss, both lookup and call are successfully, and left out here.
Datasource Definition for MySQL
In the standalone.xml, the datasource is defined as follows:
<xa-datasource jndi-name="java:jboss/datasources/MyXADS" pool-name="MyXADS_Pool" enabled="true" use-java-context="true">
<xa-datasource-property name="URL">
jdbc:mysql://localhost:3306/training1
</xa-datasource-property>
<driver>mysql</driver>
<xa-pool>
<min-pool-size>5</min-pool-size>
<max-pool-size>20</max-pool-size>
<prefill>true</prefill>
<use-strict-min>false</use-strict-min>
<flush-strategy>FailingConnectionOnly</flush-strategy>
</xa-pool>
<security>
<user-name>user</user-name>
<password>password</password>
</security>
</xa-datasource>
<drivers>
<driver name="mysql" module="com.mysql">
<xa-datasource-class>com.mysql.jdbc.jdbc2.optional.MysqlXADataSource</xa-datasource-class>
</driver>
</drivers>
If I deploy this application on a JBoss AS 7.1.1, the applications works as it should, as long as the database is MySQL.
It gets interesting if I am switching to Oracle (Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit)
Changes for Oracle
(Change 1)
The module xml for the jbdc driver, using the ojdbc6.jar, which should be ok for Oracle 11g:
<module xmlns="urn:jboss:module:1.1" name="com.oracle">
<resources>
<resource-root path="ojdbc6.jar"/>
<resource-root path="orai18n.jar"/>
</resources>
<dependencies>
<module name="javax.api"/>
<module name="javax.transaction.api"/>
</dependencies>
</module>
(Change 2)
The persistence.xml is adapted to Oracle:
<?xml version="1.0" encoding="UTF-8"?>
<persistence version="2.0" xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">
<persistence-unit name="jb7hibernate" transaction-type="JTA">
<jta-data-source>java:/PartnerDS</jta-data-source>
<class>de.protosoft.jb7hibernate.entity.Partner</class>
<properties>
<property name="hibernate.dialect" value="org.hibernate.dialect.Oracle10gDialect" />
<property name="hibernate.show_sql" value="true" />
<property name="hibernate.format_sql" value="true" />
<property name="hibernate.connection.characterEncoding" value="UTF-8" />
<property name="jboss.as.jpa.providerModule" value="org.hibernate:3" />
</properties>
</persistence-unit>
</persistence>
(Change 3)
In the standalone.xml, the datasource definition is changed to:
<xa-datasource jta="true" jndi-name="java:/PartnerDS" pool-name="PartnerDS" enabled="true" use-java-context="true" use-ccm="true">
<xa-datasource-property name="URL">
jdbc:oracle:thin:@server:1521/database
</xa-datasource-property>
<driver>oracle</driver>
<xa-pool>
<min-pool-size>10</min-pool-size>
<max-pool-size>20</max-pool-size>
<prefill>true</prefill>
<use-strict-min>false</use-strict-min>
<flush-strategy>FailingConnectionOnly</flush-strategy>
</xa-pool>
<security>
<user-name>user</user-name>
<password>password</password>
</security>
<validation>
<!--
See my note below regarding the validation checker!
<valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker"/>
-->
<validate-on-match>false</validate-on-match>
<background-validation>false</background-validation>
<stale-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker"/>
<exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExceptionSorter"/>
</validation>
<timeout>
<set-tx-query-timeout>true</set-tx-query-timeout>
<blocking-timeout-millis>5000</blocking-timeout-millis>
<idle-timeout-minutes>30</idle-timeout-minutes>
<query-timeout>120</query-timeout>
<use-try-lock>5</use-try-lock>
</timeout>
<statement>
<prepared-statement-cache-size>32</prepared-statement-cache-size>
</statement>
</xa-datasource>
<drivers>
<driver name="oracle" module="com.oracle">
<driver-class>oracle.jdbc.OracleDriver</driver-class>
<xa-datasource-class>oracle.jdbc.xa.client.OracleXADataSource</xa-datasource-class>
</driver>
</drivers>
The problem:
Let's assume that we would like to persist 10 entities at once by calling the appropriate method persist. I am using a remote EJB client.
Without using the ValidationConnectionChecker, as noted above, I can save the first entity without any problem. The second entity fails with the following exception:
2013-01-31 11:20:36,148 WARN [com.arjuna.ats.jta] (EJB default - 2) ARJUNA016039: onePhaseCommit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff82001345:-e73a376:510a4550:19, node_name=1, branch_uid=0:ffff82001345:-e73a376:510a4550:1d, subordinatenodename=null, eis_name=java:/PartnerDS > (XAResourceWrapperImpl@7b94640f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4b35542b pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options jndiName=java:/PartnerDS]) failed with exception XAException.XAER_RMFAIL: oracle.jdbc.xa.OracleXAException
at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1135) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:565) [ojdbc6.jar:11.2.0.3.0]
at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.commit(XAManagedConnection.java:334)
at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.commit(XAResourceWrapperImpl.java:90)
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:667)
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2283)
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1466)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:232) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:333) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:192) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:302) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$200(MethodInvocationMessageHandler.java:64) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:196) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.FutureTask.run(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [rt.jar:1.7.0_11]
at java.lang.Thread.run(Unknown Source) [rt.jar:1.7.0_11]
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: java.sql.SQLRecoverableException: Keine weiteren Daten aus Socket zu lesen
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1157) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.driver.T4CTTIOtxen.doOTXEN(T4CTTIOtxen.java:168) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.driver.T4CXAResource.doTransaction(T4CXAResource.java:746) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.driver.T4CXAResource.doCommit(T4CXAResource.java:422) [ojdbc6.jar:11.2.0.3.0]
at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:560) [ojdbc6.jar:11.2.0.3.0]
... 39 more
After that, the attempt to persist the third entity fails with the following exception:
2013-01-31 11:20:36,445 DEBUG [org.hibernate.util.JDBCExceptionReporter] (EJB default - 3) Cannot open connection [???]: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@213b3a43[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4b35542b connection handles=0 lastUse=1359627636289 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7656257c pool internal context=SemaphoreArrayListManagedConnectionPool@48cb2846[pool=PartnerDS] xaResource=XAResourceWrapperImpl@7b94640f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4b35542b pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options jndiName=java:/PartnerDS] txSync=null]
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:137)
at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71) [hibernate3.jar:3.6.10.Final]
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) [hibernate3.jar:3.6.10.Final]
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) [hibernate3.jar:3.6.10.Final]
at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:116) [hibernate3.jar:3.6.10.Final]
at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:109) [hibernate3.jar:3.6.10.Final]
at org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:244) [hibernate3.jar:3.6.10.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2412) [hibernate3.jar:3.6.10.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2875) [hibernate3.jar:3.6.10.Final]
at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79) [hibernate3.jar:3.6.10.Final]
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273) [hibernate3.jar:3.6.10.Final]
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:265) [hibernate3.jar:3.6.10.Final]
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184) [hibernate3.jar:3.6.10.Final]
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) [hibernate3.jar:3.6.10.Final]
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) [hibernate3.jar:3.6.10.Final]
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216) [hibernate3.jar:3.6.10.Final]
at de.protosoft.jb7hibernate.bean.PersonDataBean.persist(PersonDataBean.java:37) [jb7hibernate-0.0.1-SNAPSHOT.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_11]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) [rt.jar:1.7.0_11]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) [rt.jar:1.7.0_11]
at java.lang.reflect.Method.invoke(Unknown Source) [rt.jar:1.7.0_11]
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47) [jboss-as-jpa-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:333) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:192) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:302) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$200(MethodInvocationMessageHandler.java:64) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:196) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.FutureTask.run(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [rt.jar:1.7.0_11]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [rt.jar:1.7.0_11]
at java.lang.Thread.run(Unknown Source) [rt.jar:1.7.0_11]
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@213b3a43[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4b35542b connection handles=0 lastUse=1359627636289 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7656257c pool internal context=SemaphoreArrayListManagedConnectionPool@48cb2846[pool=PartnerDS] xaResource=XAResourceWrapperImpl@7b94640f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4b35542b pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options jndiName=java:/PartnerDS] txSync=null]
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:604)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
... 62 more
Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:474)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
... 64 more
Caused by: javax.transaction.SystemException: IJ000356: Failed to enlist: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: 0:ffff82001345:-e73a376:510a4550:20 status: ActionStatus.ABORT_ONLY >
at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.checkEnlisted(TxConnectionListener.java:552)
at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:282)
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)
... 65 more
The OracleValidConnectionChecker
Now, back to the ValidationConnectionChecker. If I enable the Checker in my configuration, the problem changes slightly. I can persist the ten entities, but it seems that I am running in some kind of timeout. During the attempt to store the second entity, I see the exception from above again:
Caused by: java.sql.SQLRecoverableException: Keine weiteren Daten aus Socket zu lesen (=>No more data to read from the socket)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1157) [ojdbc6.jar:11.2.0.3.0]
Now, during the attempt to store the third entity, I see in the logs:
2013-01-31 11:13:33,774 DEBUG [org.hibernate.pretty.Printer] (EJB default - 3) listing entities:
2013-01-31 11:13:33,774 DEBUG [org.hibernate.pretty.Printer] (EJB default - 3) de.protosoft.jb7hibernate.entity.Partner{id=CH-35614, name=Heldwein2}
2013-01-31 11:13:33,774 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] (EJB default - 3) executing flush
2013-01-31 11:13:33,774 TRACE [org.hibernate.jdbc.ConnectionManager] (EJB default - 3) registering flush begin
2013-01-31 11:13:33,774 TRACE [org.hibernate.jdbc.ConnectionManager] (EJB default - 3) registering flush end
2013-01-31 11:13:33,774 DEBUG [org.hibernate.jdbc.ConnectionManager] (EJB default - 3) aggressively releasing JDBC connection
2013-01-31 11:13:33,774 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] (EJB default - 3) post flush
2013-01-31 11:13:33,774 TRACE [org.hibernate.jdbc.JDBCContext] (EJB default - 3) before transaction completion
2013-01-31 11:13:33,774 TRACE [org.hibernate.impl.SessionImpl] (EJB default - 3) before transaction completion
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.beforeCompletion
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.beforeCompletion
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.beforeCompletion
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.beforeCompletion
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.arjuna] (EJB default - 3) BasicAction::End() for action-id 0:ffff82001345:1d688298:510a42bb:20
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.arjuna] (EJB default - 3) BasicAction::onePhaseCommit() for action-id 0:ffff82001345:1d688298:510a42bb:20
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) XAResourceRecord.topLevelOnePhaseCommit for XAResourceRecord < resource:XAResourceWrapperImpl@1b4f9688[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@623c8ba pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options jndiName=java:/PartnerDS], txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff82001345:1d688298:510a42bb:20, node_name=1, branch_uid=0:ffff82001345:1d688298:510a42bb:24, subordinatenodename=null, eis_name=java:/PartnerDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: Oracle/Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options, jndiName: java:/PartnerDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@4f747a98 >
2013-01-31 11:13:33,774 TRACE [com.arjuna.ats.jta] (EJB default - 3) XAResourceRecord.topLevelOnePhaseCommit for XAResourceRecord < resource:XAResourceWrapperImpl@1b4f9688[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@623c8ba pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options jndiName=java:/PartnerDS], txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff82001345:1d688298:510a42bb:20, node_name=1, branch_uid=0:ffff82001345:1d688298:510a42bb:24, subordinatenodename=null, eis_name=java:/PartnerDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: Oracle/Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options, jndiName: java:/PartnerDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@4f747a98 >
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.afterCompletion
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.afterCompletion
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.afterCompletion
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) SynchronizationImple.afterCompletion
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) TransactionImple.getStatus
2013-01-31 11:14:22,056 TRACE [com.arjuna.ats.jta] (EJB default - 3) TransactionImple.getStatus
2013-01-31 11:14:22,056 TRACE [org.hibernate.impl.SessionImpl] (EJB default - 3) closing session
There's a delay of almost one minute! What's happening here?
I would be glad, if someone can verify if my configuration is correct. Additionally I would appreciate it if anyone knows the reason behind this mysterious exception ("Caused by: java.sql.SQLRecoverableException: Keine weiteren Daten aus Socket zu lesen (=>No more data to read from the socket, T4CMAREngine.java:1157") or if anybody knows how to change the timeout of almost one minute.
Ciao
Christian