Hibernate and JBOSS JTA failed transactions

[smithbstl]

Using Hibernate 3.1 with JBoss 4.0.4.GA and JTA transactions. I can only get the first transaction to successfully update the database. All subsequent transactions never make it to the database. Hibernate appears to commit the transaction but JTA never commits the JTA transaction. I am a novice when it comes to Hibernate and JTA so I have attached all relevant info I could think of. Does anyone have any idea what is going on? Why these updates/transactions are so hit or miss?


Hibernate version:3.1

Mapping documents:
Har Deployment jboss-service.xml

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE jboss PUBLIC "-//JBoss//DTD JBOSS 4.0//EN"
 "http://www.jboss.org/j2ee/dtd/jboss-service_4_0.dtd">

<server>
 <mbean code="org.jboss.hibernate.jmx.Hibernate"
 name="jboss.har:service=Hibernate">
 <attribute name="DatasourceName">java:/XAOracleDS</attribute>
 <attribute name="Dialect">org.hibernate.dialect.Oracle9Dialect</attribute>
 <attribute name="SessionFactoryName">java:hibernate/SessionFactory</attribute>
 <attribute name="ShowSqlEnabled">true</attribute>
 </mbean>
</server>

Oracle Datasource

<?xml version="1.0" encoding="UTF-8"?>

<!-- ===================================================================== -->
<!-- -->
<!-- JBoss Server Configuration -->
<!-- -->
<!-- ===================================================================== -->

<!-- $Id: oracle-xa-ds.xml,v 1.13 2004/09/15 14:37:40 loubyansky Exp $ -->

<!-- ===================================================================== -->
<!-- ATTENTION: DO NOT FORGET TO SET Pad=true IN transaction-service.xml -->
<!-- ===================================================================== -->

<datasources>
 <xa-datasource>
 <jndi-name>XAOracleDS</jndi-name>
 <track-connection-by-tx/>
 <isSameRM-override-value>false</isSameRM-override-value>
 <xa-datasource-class>oracle.jdbc.xa.client.OracleXADataSource</xa-datasource-class>
 <!--<xa-datasource-property name="URL">jdbc:oracle:oci8:@tc</xa-datasource-property>-->
 <!--<xa-datasource-property name="User">scott</xa-datasource-property>-->
 <!--<xa-datasource-property name="Password">tiger</xa-datasource-property>-->
 <xa-datasource-property name="URL">jdbc:oracle:thin:@192.168.193.133:1521:ora1</xa-datasource-property>
 <xa-datasource-property name="User">budget_access</xa-datasource-property>
 <xa-datasource-property name="Password">budget_access</xa-datasource-property>


 <!-- Uses the pingDatabase method to check a connection is still valid before handing it out from the pool -->
 <!--valid-connection-checker-class-name>org.jboss.resource.adapter.jdbc.vendor.OracleValidConnectionChecker</valid-connection-checker-class-name-->
 <!-- Checks the Oracle error codes and messages for fatal errors -->
 <exception-sorter-class-name>org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter</exception-sorter-class-name>
 <!-- Oracles XA datasource cannot reuse a connection outside a transaction once enlisted in a global transaction and vice-versa -->
 <no-tx-separate-pools/>
 <!--pooling parameters-->
 <min-pool-size>1</min-pool-size>
 <max-pool-size>100</max-pool-size>
 <blocking-timeout-millis>5000</blocking-timeout-millis>
 <idle-timeout-minutes>15</idle-timeout-minutes>
 <!-- corresponding type-mapping in the standardjbosscmp-jdbc.xml (optional) -->
 <metadata>
 <type-mapping>Oracle9i</type-mapping>
 </metadata>
 </xa-datasource>

 <mbean code="org.jboss.resource.adapter.jdbc.vendor.OracleXAExceptionFormatter"
 name="jboss.jca:service=OracleXAExceptionFormatter">
 <depends optional-attribute-name="TransactionManagerService">jboss:service=TransactionManager</depends>
 </mbean>

</datasources>

Code between sessionFactory.openSession() and session.close():
JNDI Lookups for Session

public static SessionFactory getHibernateSessionFactory(String jndiSessionFactoryName) throws ServiceLocatorException {
 SessionFactory sessionFactory = null;

 try {
 Context ctx = new InitialContext();
 sessionFactory = (SessionFactory) ctx.lookup(jndiSessionFactoryName);

 } catch (ClassCastException cce) {
 throw new ServiceLocatorException(cce);
 } catch (NamingException ne) {
 throw new ServiceLocatorException(ne);
 }

 return sessionFactory;
 }

 public static Session getHibernateSession(String jndiSessionFactoryName) throws ServiceLocatorException {
 Session session = null;

 try {
 session = getHibernateSessionFactory(jndiSessionFactoryName).openSession();
 }
 catch (Exception e) {
 throw new ServiceLocatorException(e);
 }
 return session;
 }

DAO logic

 public void update(AccountBean acctBean) {
 Session session = null;
 Transaction tx = null;
 try {
 session = ServiceLocator.getHibernateSession(HIBERNATE_SESSION_FACTORY);
 tx = session.beginTransaction();
 session.update(acctBean);
 tx.commit();
 } catch (Exception e) {
 try {
 tx.rollback();
 } catch (Exception e2) {
 System.out.println(e2);
 }
 System.out.println(e);
 } finally {
 try {
 if (session != null) {
 session.close();
 }
 } catch (Exception e) {
 System.out.println(e);
 }
 }
 }

server logs:
Log of successful transaction
2006-08-04 14:42:56,344 INFO [STDOUT] Save Called
2006-08-04 14:42:56,344 INFO [STDOUT] AccountSave: AcctID = 307 AcctNum = 5105 AcctName = Salaries - Tempy Employees
2006-08-04 14:42:56,360 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-04 14:42:56,360 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cdab53f010cdab540a90000
2006-08-04 14:42:56,360 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-08-04 14:42:56,360 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4729735480770560
2006-08-04 14:42:56,360 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-04 14:42:56,360 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-04 14:42:56,360 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-04 14:42:56,360 DEBUG [org.hibernate.transaction.JTATransaction] Began a new JTA transaction
2006-08-04 14:42:56,360 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-04 14:42:56,375 DEBUG [org.hibernate.transaction.JTATransaction] commit
2006-08-04 14:42:56,375 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-08-04 14:42:56,375 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2006-08-04 14:42:56,391 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
2006-08-04 14:42:56,391 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-08-04 14:42:56,391 DEBUG [org.hibernate.pretty.Printer] listing entities:
2006-08-04 14:42:56,391 DEBUG [org.hibernate.pretty.Printer] com.stlouiscity.budget.database.beans.AccountBean{acctNum=5105, acctName=Salaries - Tempy Employees, acctId=307}
2006-08-04 14:42:56,391 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-08-04 14:42:56,391 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-08-04 14:42:56,454 DEBUG [org.hibernate.SQL] update Budget.Account set Acct_Num=?, Acct_Name=? where Acct_ID=?
2006-08-04 14:42:56,454 INFO [STDOUT] Hibernate: update Budget.Account set Acct_Num=?, Acct_Name=? where Acct_ID=?
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.AbstractBatcher] success of batch update unknown: 0
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-08-04 14:42:56,454 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-08-04 14:42:56,454 DEBUG [org.hibernate.transaction.JTATransaction] Committed JTA UserTransaction
2006-08-04 14:42:56,454 INFO [STDOUT] org.hibernate.SessionException: Session was already closed
2006-08-04 14:42:56,469 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-04 14:42:56,469 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cdab53f010cdab540a90000
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-08-04 14:42:56,469 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4729735481217024
2006-08-04 14:42:56,469 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-04 14:42:56,469 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-04 14:42:56,469 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-04 14:42:56,469 DEBUG [org.hibernate.transaction.JTATransaction] Began a new JTA transaction
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-08-04 14:42:56,469 DEBUG [org.hibernate.SQL] select accountbea0_.Acct_ID as Acct1_0_, accountbea0_.Acct_Num as Acct2_0_, accountbea0_.Acct_Name as Acct3_0_ from Budget.Account accountbea0_ order by accountbea0_.Acct_Num
2006-08-04 14:42:56,469 INFO [STDOUT] Hibernate: select accountbea0_.Acct_ID as Acct1_0_, accountbea0_.Acct_Num as Acct2_0_, accountbea0_.Acct_Name as Acct3_0_ from Budget.Account accountbea0_ order by accountbea0_.Acct_Num
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-08-04 14:42:56,469 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:42:56,469 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections

Log of unsuccessful transaction
2006-08-04 14:43:07,891 INFO [STDOUT] Save Called
2006-08-04 14:43:07,891 INFO [STDOUT] AccountSave: AcctID = 167 AcctNum = 5104 AcctName = Salaries - Adjustments
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cdab53f010cdab540a90000
2006-08-04 14:43:07,907 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4729735528067072
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] commit
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cdab53f010cdab540a90000
2006-08-04 14:43:07,907 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-04 14:43:07,907 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4729735528067073
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-04 14:43:07,907 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-04 14:43:07,907 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-08-04 14:43:07,907 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-08-04 14:43:07,907 DEBUG [org.hibernate.SQL] select accountbea0_.Acct_ID as Acct1_0_, accountbea0_.Acct_Num as Acct2_0_, accountbea0_.Acct_Name as Acct3_0_ from Budget.Account accountbea0_ order by accountbea0_.Acct_Num
2006-08-04 14:43:07,907 INFO [STDOUT] Hibernate: select accountbea0_.Acct_ID as Acct1_0_, accountbea0_.Acct_Num as Acct2_0_, accountbea0_.Acct_Name as Acct3_0_ from Budget.Account accountbea0_ order by accountbea0_.Acct_Num
2006-08-04 14:43:07,907 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-08-04 14:43:07,907 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:43:07,907 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:43:07,907 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:43:07,907 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-08-04 14:43:07,922 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-08-04 14:43:07,922 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-08-04 14:43:07,922 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#164]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#165]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#166]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#167]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#168]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.stlouiscity.budget.database.beans.AccountBean#307]
2006-08-04 14:43:07,922 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections

Name and version of the database you are using:Oracle 10g Release 1 - JDBC Thin Driver

[smithbstl]

I am still dealing with this issue, does anyone have any ideas?

its just weird because some transactions work, some fail. I would say about 25% work

here are some shorter more recent server logs that illustrate the problem

Unsuccessful Transaction
2006-08-10 11:55:54,031 INFO [STDOUT] Update Called
2006-08-10 11:55:54,031 INFO [STDOUT] ***Account Save***
2006-08-10 11:55:54,031 INFO [STDOUT] AcctID: 325
2006-08-10 11:55:54,031 INFO [STDOUT] AcctNum: 5106
2006-08-10 11:55:54,031 INFO [STDOUT] AcctName: Test3
2006-08-10 11:55:54,031 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-10 11:55:54,031 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cf90095010cf900970d0000
2006-08-10 11:55:54,031 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-10 11:55:54,031 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4731817795710976
2006-08-10 11:55:54,031 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-10 11:55:54,031 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-10 11:55:54,031 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-10 11:55:54,031 DEBUG [org.hibernate.transaction.JTATransaction] commit

Successful Transaction
2006-08-10 11:56:14,578 INFO [STDOUT] Update Called
2006-08-10 11:56:14,578 INFO [STDOUT] ***Account Save***
2006-08-10 11:56:14,578 INFO [STDOUT] AcctID: 167
2006-08-10 11:56:14,578 INFO [STDOUT] AcctNum: 5104
2006-08-10 11:56:14,578 INFO [STDOUT] AcctName: Salaries - Adjustments
2006-08-10 11:56:14,578 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: hibernate/SessionFactory
2006-08-10 11:56:14,578 DEBUG [org.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=402882a50cf90095010cf900970d0000
2006-08-10 11:56:14,578 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-08-10 11:56:14,578 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4731817879871488
2006-08-10 11:56:14,578 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2006-08-10 11:56:14,578 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2006-08-10 11:56:14,578 DEBUG [org.hibernate.transaction.JTATransaction] begin
2006-08-10 11:56:14,578 DEBUG [org.hibernate.transaction.JTATransaction] Began a new JTA transaction
2006-08-10 11:56:14,578 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-08-10 11:56:14,578 DEBUG [org.hibernate.transaction.JTATransaction] commit
2006-08-10 11:56:14,578 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-08-10 11:56:14,578 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2006-08-10 11:56:14,578 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
2006-08-10 11:56:14,578 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-08-10 11:56:14,578 DEBUG [org.hibernate.pretty.Printer] listing entities:
2006-08-10 11:56:14,578 DEBUG [org.hibernate.pretty.Printer] com.stlouiscity.budget.database.beans.AccountBean{acctNum=5104, acctName=Salaries - Adjustments, acctId=167}
2006-08-10 11:56:14,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-08-10 11:56:14,578 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-08-10 11:56:14,625 DEBUG [org.hibernate.SQL] update Budget.Account set Acct_Num=?, Acct_Name=? where Acct_ID=?
2006-08-10 11:56:14,625 INFO [STDOUT] Hibernate: update Budget.Account set Acct_Num=?, Acct_Name=? where Acct_ID=?
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.AbstractBatcher] success of batch update unknown: 0
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-08-10 11:56:14,625 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-08-10 11:56:14,625 DEBUG [org.hibernate.transaction.JTATransaction] Committed JTA UserTransaction

[smithbstl]

Anyone? It seems fairly random whether a transaction will commit or not. I can do an update to the database then do a select when the page reloads and the update has not been commited because I get the old data back. Can someone point me in some kind of direction so I can begin to troubleshoot this?

[jmcclure]

Hi,

I'm using JBoss 4.0.4GA and Hibernate 3.1 with Sybase 12.5 and I get the same scenario. My initial indication of something wrong is
2006-08-30 17:24:32,988 WARN [org.jboss.tm.TransactionImpl] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=ATXWS-2606/27, BranchQual=, localId=27] timed out. status=STATUS_ACTIVE

Do you have any other information on this topic? I'm struggling to get this resolved. Thanks.

james

[smithbstl]

Nope, I am still having this problem. I am still in development on my project and have swapped in jdbc for the time being and moved on. Please post back if you get this resolved.

[smithbstl]

I have solved my problem, It turns out that I was not wrapping my Hibernate sessions in UserTransactions. I should have been using a local-tx connection instead of an XA connection. Much thanks to Weston Price for helping me out on this one.

This may be useful for anyone who does not have a good grasp of JTA UserTransactions like I didn't. This deals with JDBC instead of Hibernate but the same logic applies
http://jboss.org/index.html?module=bb&op=viewtopic&p=3969854

Here is another Hibernate specific resource.
http://www.hibernate.org/42.html

[ggreaves]

Could you be more specific as to what you did to solve this. I am using a local-tx connection and still having the:

SessionException: Session was already closed

when I try to manually close the session. BTW, this is specific behaviour to version 4.0.4. In 4.0.3, with the same connection and hibernate-service.xml, it works fine.

Here are the files in question:

=========== hibernate-service.xml ==========

<server>
 <mbean code="org.jboss.hibernate.jmx.Hibernate"
 name="jboss.har:service=Hibernate">
 <attribute name="DatasourceName">java:/CRMDS</attribute>
 <attribute name="Dialect">org.hibernate.dialect.MySQLDialect</attribute>
 <attribute name="SessionFactoryName">java:/hibernate/HibernateSessionFactory</attribute>
 <attribute name="CacheProviderClass">org.hibernate.cache.HashtableCacheProvider</attribute>
 <attribute name="Hbm2ddlAuto">update</attribute>
 <attribute name="ShowSqlEnabled">true</attribute>
 </mbean>
</server>

=========== hibernate-service.xml ==========

=========== datasource ===============

<datasources>
 <local-tx-datasource>
 <jndi-name>CRMDS</jndi-name>
 <connection-url>jdbc:mysql://localhost:3306/crmdb</connection-url>
 <driver-class>org.gjt.mm.mysql.Driver</driver-class>
 <user-name>blah</user-name>
 <password>blah</password>
 <exception-sorter-class-name>org.jboss.resource.adapter.jdbc.vendor.MySQLExceptionSorter</exception-sorter-class-name>
 <!-- sql to call when connection is created
 <new-connection-sql>some arbitrary sql</new-connection-sql>
 -->
 <!-- sql to call on an existing pooled connection when it is obtained from pool
 <check-valid-connection-sql>some arbitrary sql</check-valid-connection-sql>
 -->

 <!-- corresponding type-mapping in the standardjbosscmp-jdbc.xml (optional) -->
 <metadata>
 <type-mapping>mySQL</type-mapping>
 </metadata>
 </local-tx-datasource>
</datasources>

=========== datasource ===============

Any ideas?

[ggreaves]

To illustrate the code in question:

protected void closeSession() {
 if ( this.getSession().isOpen() ) {
 this.getSession().getTransaction().commit();
 this.getSession().close();
 }
}

When it gets into the "if", the session is open. After the commit, the session is closed. Thus, calling this.getSession().close() throws the "Session is already closed" exception. Why is the commit closing the session?

BTW, this behaviour only happens on 4.0.04GA and not 4.0.03 with identical datasource / Hibernate configurations.

[arupsarkar]

Did any of you use myeclipse ide for developing hibernate, I am getting the following error while deploying.

"No ClassLoaders found for: net.sf.hibernate.jmx.HibernateService" I am using JBoss 4.0.2

Regards
Arup

[smithbstl]

ggreaves: I think with Jboss 4.0.4, you must name your hibernate-service.xml file jboss-service.xml I am not sure this became necessary but it did.
Here is how I am using JTA Transactions with Hibernate

I created a transaction service helper that basically just does exception handling

package com.stlouiscity.util;
import javax.transaction.*;

public class TransactionService {

 /**
 * Creates a new instance of TransactionService
 */
 public TransactionService() {
 }
 public static UserTransaction getUserTransaction() {
 UserTransaction ut = null;
 ut = ServiceLocator.getUserTransaction();
 return ut;
 }

 public static void beginUserTransaction(UserTransaction ut) {
 try {
 ut.begin();
 } catch(NotSupportedException nse) {
 throw new TransactionServiceException(nse);
 } catch(SystemException se) {
 throw new TransactionServiceException(se);
 }
 }

 public static void commitUserTransaction(UserTransaction ut) {
 try {
 ut.commit();
 } catch (RollbackException re) {
 throw new TransactionServiceException(re);
 } catch (HeuristicMixedException hme) {
 throw new TransactionServiceException(hme);
 } catch (HeuristicRollbackException hre) {
 throw new TransactionServiceException(hre);
 } catch (java.lang.SecurityException se) {
 throw new TransactionServiceException(se);
 } catch (java.lang.IllegalStateException ise) {
 throw new TransactionServiceException(ise);
 } catch (SystemException syse) {
 throw new TransactionServiceException(syse);
 }
 }

 public static void rollbackUserTransaction(UserTransaction ut) {
 try {
 ut.rollback();
 } catch (java.lang.IllegalStateException ise) {
 throw new TransactionServiceException(ise);
 } catch (java.lang.SecurityException se) {
 throw new TransactionServiceException(se);
 } catch (SystemException syse) {
 throw new TransactionServiceException(syse);
 }
 }
}

Here is the TransactionServiceException Class

public class TransactionServiceException extends RuntimeException {

 /**
 * Creates a new instance of TransactionServiceException
 */
 public TransactionServiceException() {
 super();
 }

 public TransactionServiceException(String message) {
 super(message);
 }

 public TransactionServiceException(Throwable cause) {
 super(cause);
 }

 public TransactionServiceException(String message, Throwable cause) {
 super(message, cause);
 }

}

Here is the actual DAO logic

package com.stlouiscity.budget.database.dao;

import com.stlouiscity.budget.database.beans.AccountBean;
import com.stlouiscity.database.util.HibernateUtil;
import com.stlouiscity.util.TransactionService;
import com.stlouiscity.util.ServiceLocator;

import java.util.List;
import java.util.Iterator;

import javax.transaction.UserTransaction;

import org.hibernate.Session;
import org.hibernate.Query;
import org.hibernate.Transaction;

public class AccountDAOHibernateImpl implements AccountDAO {

 private long minRange;
 private long maxRange;
 private static final String HIBERNATE_SESSION_FACTORY
 = "java:comp/env/hibernate/SessionFactory";

 /** Creates a new instance of AccountDAOImpl */
 public AccountDAOHibernateImpl() {
 }
 public void update(AccountBean acctBean) {
 Session session = null;
 UserTransaction ut = null;
 try {
 ut = TransactionService.getUserTransaction();
 TransactionService.beginUserTransaction(ut);
 session = ServiceLocator.getHibernateSession(HIBERNATE_SESSION_FACTORY);
 session.update(acctBean);
 TransactionService.commitUserTransaction(ut);
 } catch (Exception e) {
 System.out.println(e);
 TransactionService.rollbackUserTransaction(ut);
 } finally {
 try {
 if (session !=null) {
 if (session.isOpen()) {
 session.close();
 }
 }
 } catch (Exception e) {
 System.out.println(e);
 }
 }
 }

Here is HibernateUtil - I think i copied it from Hibernate In Action

package com.stlouiscity.database.util;
import org.hibernate.*;
import org.hibernate.cfg.*;

public class HibernateUtil {

 private static final SessionFactory sessionFactory;
 /** Creates a new instance of HibernateUtil */

 static {
 try {
 sessionFactory = new Configuration().configure().buildSessionFactory();
 } catch (Throwable ex) {
 System.err.println("Initial SessionFactory creation failed." + ex);
 throw new ExceptionInInitializerError(ex);
 }
 }
 public static SessionFactory getSessionFactory() {
 return sessionFactory;
 }
}

I hope this help you sort it out