Hibernate version:
3.1
Mapping documents:
N/A. This is a JOTM/JTA issue
Code between sessionFactory.openSession() and session.close():
Not invoked, following examples of just using sessionFactory.getCurrentSession(), and using JTA UserTransaction methods to demark TX boundaries.
Full stack trace of any exception that occurs:
n/a
Name and version of the database you are using:
Oracle 10g R2
The generated SQL (show_sql=true):
n/a
Debug level Hibernate log excerpt:

See below description of problem:

I'm trying to create a setup by which I can use JTA in both container (Weblogic) and standalone (unit test and CLI applications) in Hibernate. I got it up and running, after a certain amount of difficulty configurin JOTM (most of the issues were with JNDI and CAROL, see below).

The short story is that in my test application, I intentionally throw an exception to test the rollback, and while the logs report a successful rollback, a query made through an external client (TOAD) shows that data was WRITTEN to the database.

Other observations:

If I use the UserTransaction methods (JTA) to demark TX boundaries, the app will run to completion.

If I use the Transaction methods, the JNDI lookup performed by CAROL looks in a different InitialContext than the one I've set up using System properties. It sees "java" as a protocol when inspecting the name "java:comp/UserTransaction", and looks in a Context other than the ResFSContext that I've created.

I pretty much had to use the ResFSContext to get this to run, given JOTM's dependence on CAROL.

CAROL docs recommend setting the supported protocol to "lmi" (local method invocation", but as you can see from the stack trace in the log, it can't recognize lmi. However, at least it doesn't totally bomb out.

Given the TX ID's I see in the log, it does not look as if I am working with two different transactions.

Questions:

Do I have to explicitly bind my UserTransaction to JNDI, or will JOTM or the SessionFactory do that for me?

Do I need to explicitly start it before binding, or should I bind, then retrieve (when needed), then begin?

Here's the relevant info. Hibernate log, followed by java code, and config file. Note that even though the JNDI name for the datasource has "weblogic" in it, the name is constant (even if I'm not running in a managed container).

Thanks in advance to anyone who can help me out. I'm new to Hibernate, and while I've made some headway in the last couple days, the whole Hibernate/JTA/JNDI/CAROL/JOTM stack has been giving me headaches. Now I'm almost there, I just need my TX to rollback correctly.

Matt Geis

------------

Hibernate Log

Buildfile: D:\eclipse3.1.1\eclipse\workspace\TVHibernate\build.xml
init:
compile:
[javac] Compiling 1 source file to D:\eclipse3.1.1\eclipse\workspace\TVHibernate\build
run:
[java] 0 [main] INFO org.objectweb.jotm - JOTM started with a local transaction factory which is not bound.
[java] 10 [main] INFO org.objectweb.jotm - CAROL initialization
[java] 80 [main] DEBUG org.objectweb.carol.util.configuration.ConfigurationRepository - Build protocol object for protocol name found 'cmi'.
[java] 100 [main] DEBUG org.objectweb.carol.util.configuration.ConfigurationRepository - Cmi is not available, don't configure it.
[java] 100 [main] DEBUG org.objectweb.carol.util.configuration.ConfigurationRepository - Build protocol object for protocol name found 'jeremie'.
[java] 100 [main] DEBUG org.objectweb.carol.util.configuration.ConfigurationRepository - Build protocol object for protocol name found 'iiop'.
[java] 100 [main] DEBUG org.objectweb.carol.util.configuration.ConfigurationRepository - Build protocol object for protocol name found 'jrmp'.
[java] 130 [main] ERROR org.objectweb.jotm - CAROL initialization failed
[java] org.objectweb.carol.util.configuration.ConfigurationException: Cannot find a protocol with name 'lmi' in the list of available protocols.
[java] at org.objectweb.carol.util.configuration.ConfigurationRepository.init(ConfigurationRepository.java:335)
[java] at org.objectweb.carol.util.configuration.ConfigurationRepository.init(ConfigurationRepository.java:229)
[java] at org.objectweb.carol.util.configuration.ConfigurationRepository.init(ConfigurationRepository.java:397)
[java] at org.objectweb.jotm.Jotm.<init>(Jotm.java:133)
[java] at Hello.main(Hello.java:49)
[java] 240 [main] DEBUG org.objectweb.jotm - default constructor
[java] 380 [main] INFO org.objectweb.jotm.jta - JOTM 2.0.10
[java] 390 [main] DEBUG org.objectweb.jotm.jta - TransactionFactory=org.objectweb.jotm.TransactionFactoryImpl@13f3045
[java] 400 [main] DEBUG org.objectweb.jotm.jta - Batch constructor
[java] 410 [main] DEBUG org.objectweb.jotm.jta - Clock constructor
[java] 460 [main] DEBUG org.objectweb.jotm.recovery - TransactionRecoveryImpl constructor
[java] 460 [main] DEBUG org.objectweb.jotm.recovery - JOTM Recovery is disabled
[java] 460 [main] DEBUG org.objectweb.jotm - UserTransaction=org.objectweb.jotm.Current@1adc30
[java] 460 [main] DEBUG org.objectweb.jotm.jta - begin transaction
[java] 460 [main] DEBUG org.objectweb.jotm.jta - threadTx.get= java.lang.ThreadLocal@16df84b
[java] 641 [main] DEBUG org.objectweb.jotm.jta - xid= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 641 [main] DEBUG org.objectweb.jotm.jta - timeout= 60
[java] 651 [main] DEBUG org.objectweb.jotm.jta - xid=bb14:38:0:01ead731021646dd4c...78fc01:, timeout=60
[java] 651 [main] DEBUG org.objectweb.jotm.jta - tx=bb14:38:0:01ead731021646dd4c...78fc01:
[java] 661 [main] DEBUG org.objectweb.jotm.jta - TransactionImpl.doAttach flag= TMJOIN
[java] 661 [main] DEBUG org.objectweb.jotm.jta - number of enlisted= 0
[java] 661 [main] DEBUG org.objectweb.jotm.jta - threadTx.set= java.lang.ThreadLocal@16df84b
[java] 661 [main] DEBUG org.objectweb.jotm.jta - Associate tx to xid (xid=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 671 [main] DEBUG org.objectweb.jotm.jta - TimerEvent.new(bb14:38:0:01ead731021646dd4c...78fc01:,60,null,false)
[java] 671 [main] DEBUG org.objectweb.jotm.jta - set timer for tx (timer=org.objectweb.jotm.TimerEvent@a6d51e,

tx=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 671 [main] DEBUG org.objectweb.jotm.jta - set date for tx (data=Tue Jan 17 18:00:47 PST 2006, tx=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 691 [main] DEBUG org.objectweb.jotm.jta - Current.getReference()
[java] 881 [main] INFO org.hibernate.cfg.Environment - Hibernate 3.1
[java] 921 [main] INFO org.hibernate.cfg.Environment - hibernate.properties not found
[java] 931 [main] INFO org.hibernate.cfg.Environment - using CGLIB reflection optimizer
[java] 931 [main] INFO org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling
[java] 1662 [main] INFO org.hibernate.cfg.Configuration - configuring from resource: hibernate_test/aidadb.cfg.xml
[java] 1662 [main] INFO org.hibernate.cfg.Configuration - Configuration resource: hibernate_test/aidadb.cfg.xml
[java] 2083 [main] DEBUG org.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in

classpath under org/hibernate/
[java] 2093 [main] DEBUG org.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.transaction.factory_class=org.hibernate.transaction.JTATransactionFactory
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration -

hibernate.transaction.manager_lookup_class=org.hibernate.transaction.WeblogicTransactionManagerLookup
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.connection.datasource=weblogic.jdbc.jts.AidaDbPool
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.session_factory_name=TVSessionFactory
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.dialect=org.hibernate.dialect.OracleDialect
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.current_session_context_class=jta
[java] 2393 [main] DEBUG org.hibernate.cfg.Configuration - hibernate.show_sql=true
[SNIP -- LOTS OF HIBERNATE MAPPING CONFIGURATION]
[java] 9775 [main] INFO org.hibernate.cfg.Configuration - Configured SessionFactory: null
[SNIP -- LOTS OF ENVIRONMENT OUTPUT]
[java] 9785 [main] DEBUG org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
[java] 9785 [main] INFO org.hibernate.cfg.Configuration - processing extends queue
[java] 9785 [main] INFO org.hibernate.cfg.Configuration - processing collection mappings
[SNIP -- LOTS OF COLLECTION MAPPINGS]
[SNIP -- LOTS OF ASSOCIATION PROCESSING]
[java] 13720 [main] INFO org.hibernate.util.NamingHelper - JNDI InitialContext properties:{}
[java] 13781 [main] INFO org.hibernate.connection.DatasourceConnectionProvider - Using datasource: weblogic.jdbc.jts.AidaDbPool
[java] 17316 [main] INFO org.hibernate.cfg.SettingsFactory - RDBMS: Oracle, version: Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bit

Production
[java] With the Partitioning, OLAP and Data Mining options
[java] 17316 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC driver: Oracle JDBC driver, version: 10.1.0.4.0
[java] 17596 [main] INFO org.hibernate.dialect.Dialect - Using dialect: org.hibernate.dialect.OracleDialect
[java] 17787 [main] INFO org.hibernate.transaction.TransactionFactoryFactory - Transaction strategy: org.hibernate.transaction.JTATransactionFactory
[java] 17807 [main] INFO org.hibernate.util.NamingHelper - JNDI InitialContext properties:{}
[java] 17817 [main] INFO org.hibernate.transaction.TransactionManagerLookupFactory - instantiating TransactionManagerLookup:

org.hibernate.transaction.JOTMTransactionManagerLookup
[java] 17837 [main] INFO org.hibernate.transaction.TransactionManagerLookupFactory - instantiated TransactionManagerLookup
[java] 17837 [main] INFO org.hibernate.transaction.TransactionManagerLookupFactory - instantiating TransactionManagerLookup:

org.hibernate.transaction.JOTMTransactionManagerLookup
[java] 17837 [main] INFO org.hibernate.transaction.TransactionManagerLookupFactory - instantiated TransactionManagerLookup
[java] 17837 [main] INFO org.hibernate.cfg.SettingsFactory - Automatic flush during beforeCompletion(): disabled
[java] 17837 [main] INFO org.hibernate.cfg.SettingsFactory - Automatic session close at end of transaction: disabled
[java] 17837 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC batch size: 15
[java] 17837 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC batch updates for versioned data: disabled
[java] 17847 [main] INFO org.hibernate.cfg.SettingsFactory - Scrollable result sets: enabled
[java] 17847 [main] DEBUG org.hibernate.cfg.SettingsFactory - Wrap result sets: disabled
[java] 17847 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC3 getGeneratedKeys(): disabled
[java] 17847 [main] INFO org.hibernate.cfg.SettingsFactory - Connection release mode: auto
[java] 17857 [main] INFO org.hibernate.cfg.SettingsFactory - Default batch fetch size: 1
[java] 17857 [main] INFO org.hibernate.cfg.SettingsFactory - Generate SQL with comments: disabled
[java] 17857 [main] INFO org.hibernate.cfg.SettingsFactory - Order SQL updates by primary key: disabled
[java] 17857 [main] INFO org.hibernate.cfg.SettingsFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
[java] 17917 [main] INFO org.hibernate.hql.ast.ASTQueryTranslatorFactory - Using ASTQueryTranslatorFactory
[java] 17917 [main] INFO org.hibernate.cfg.SettingsFactory - Query language substitutions: {}
[java] 17917 [main] INFO org.hibernate.cfg.SettingsFactory - Second-level cache: enabled
[java] 17917 [main] INFO org.hibernate.cfg.SettingsFactory - Query cache: disabled
[java] 17917 [main] INFO org.hibernate.cfg.SettingsFactory - Cache provider: org.hibernate.cache.EhCacheProvider
[java] 17977 [main] INFO org.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: disabled
[java] 17977 [main] INFO org.hibernate.cfg.SettingsFactory - Structured second-level cache entries: disabled
[java] 17997 [main] DEBUG org.hibernate.exception.SQLExceptionConverterFactory - Using dialect defined converter
[java] 18097 [main] INFO org.hibernate.cfg.SettingsFactory - Echoing all SQL to stdout
[java] 18097 [main] INFO org.hibernate.cfg.SettingsFactory - Statistics: disabled
[java] 18097 [main] INFO org.hibernate.cfg.SettingsFactory - Deleted entity synthetic identifier rollback: disabled
[java] 18097 [main] INFO org.hibernate.cfg.SettingsFactory - Default entity-mode: pojo
[java] 18438 [main] INFO org.hibernate.impl.SessionFactoryImpl - building session factory
[java] 18438 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - Session factory constructed with filter configurations : {}
[SNIP -- MORE SYSTEM PROPERTIES]
[java] 18518 [main] WARN net.sf.ehcache.config.Configurator - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the

classpath: jar:file:/D:/javaclasses/hibernate-3.1/lib/ehcache-1.1.jar!/ehcache-failsafe.xml
[SNIP -- LOTS OF STATIC SQL STATEMENT CREATION]
\
[java] 26640 [main] DEBUG org.hibernate.impl.SessionFactoryObjectFactory - initializing class SessionFactoryObjectFactory
[java] 26660 [main] DEBUG org.hibernate.impl.SessionFactoryObjectFactory - registered: 8aae84d508db3e630108db3e83ce0000 (TVSessionFactory)
[java] 26660 [main] INFO org.hibernate.impl.SessionFactoryObjectFactory - Factory name: TVSessionFactory
[java] 26660 [main] INFO org.hibernate.util.NamingHelper - JNDI InitialContext properties:{}
[java] 26660 [main] DEBUG org.hibernate.util.NamingHelper - binding: TVSessionFactory
[java] 26700 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - Returning a Reference to the SessionFactory
[java] 26700 [main] DEBUG org.hibernate.util.NamingHelper - Bound name: TVSessionFactory
[java] 26700 [main] INFO org.hibernate.impl.SessionFactoryObjectFactory - Bound factory to JNDI name: TVSessionFactory
[java] 26700 [main] WARN org.hibernate.impl.SessionFactoryObjectFactory - InitialContext did not implement EventContext
[java] 26700 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - instantiated session factory
[java] 26700 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - obtaining JTA TransactionManager
[java] 26830 [main] INFO org.hibernate.impl.SessionFactoryImpl - Checking 0 named HQL queries
[java] 26830 [main] INFO org.hibernate.impl.SessionFactoryImpl - Checking 0 named SQL queries
[java] 26850 [main] DEBUG org.hibernate.impl.SessionFactoryObjectFactory - JNDI lookup: TVSessionFactory
[java] 26850 [main] DEBUG org.hibernate.impl.SessionFactoryObjectFactory - lookup: uid=8aae84d508db3e630108db3e83ce0000
[java] 18:01:14,003 - DEBUG JNDI lookup: TVSessionFactory
[java] 18:01:14,003 - DEBUG lookup: uid=8aae84d508db3e630108db3e83ce0000
[java] 18:01:14,003 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:14,003 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:14,003 - DEBUG TransactionImpl.getStatus()
[java] 18:01:14,533 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:14,533 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:14,533 - DEBUG TransactionImpl.getStatus()
[java] 18:01:14,564 - DEBUG TransactionImpl.registerSynchronization(Synchronization sync)
[java] 18:01:14,564 - DEBUG make subcoordinator
[java] 18:01:14,594 - DEBUG tx=bb14:38:0:01ead731021646dd4c...78fc01:, xid=bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:14,594 - DEBUG synchro=org.hibernate.transaction.CacheSynchronization
[java] 18:01:14,624 - DEBUG status=STATUS_ACTIVE
[java] 18:01:14,624 - DEBUG successfully registered Synchronization
[java] 18:01:14,624 - DEBUG opened session at timestamp: 4659403466149888
[java] 18:01:14,634 - DEBUG TransactionImpl.registerSynchronization(Synchronization sync)
[java] 18:01:14,644 - DEBUG synchro=org.hibernate.context.JTASessionContext$CleanupSynch@1a4181c
[java] 18:01:14,644 - DEBUG status=STATUS_ACTIVE
[SNIP -- MORE LOW-LEVEL QUERY DEBUG STATEMENTS]
[java] 18:01:20,983 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:20,983 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:20,983 - DEBUG TransactionImpl.getStatus()
[java] 18:01:20,983 - DEBUG status=STATUS_ACTIVE
[java] 18:01:20,983 - DEBUG aggressively releasing JDBC connection
[java] 18:01:20,983 - DEBUG closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 18:01:20,993 - DEBUG total objects hydrated: 0
[java] 18:01:20,993 - DEBUG initializing non-lazy collections
[java] 18:01:20,993 - DEBUG done entity load
[java] 18:01:20,993 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:20,993 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:20,993 - DEBUG TransactionImpl.getStatus()
[java] 18:01:20,993 - DEBUG status=STATUS_ACTIVE
[java] No password standard found for ID of 3
[java] adding record to hibernate...
[java] 18:01:20,993 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:20,993 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:20,993 - DEBUG TransactionImpl.getStatus()
[java] 18:01:20,993 - DEBUG status=STATUS_ACTIVE
[java] 18:01:21,063 - DEBUG id unsaved-value strategy UNDEFINED
[SNIP -- DEBUG INFO FOR SAVE/UPDATE]
[java] 18:01:21,183 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:21,183 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:21,183 - DEBUG TransactionImpl.getStatus()
[java] 18:01:21,183 - DEBUG status=STATUS_ACTIVE
[java] 18:01:21,183 - DEBUG aggressively releasing JDBC connection
[java] 18:01:21,183 - DEBUG closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 18:01:21,183 - DEBUG transient instance of: hibernate_test.PasswordStandard
[java] 18:01:21,183 - DEBUG saving transient instance
[java] 18:01:21,183 - DEBUG generated identifier: 3, using strategy: org.hibernate.id.Assigned
[java] 18:01:21,183 - DEBUG saving [hibernate_test.PasswordStandard#3]
[java] 18:01:21,294 - DEBUG Wrapped collection in role: hibernate_test.PasswordStandard.tradingPasswords
[java] 18:01:21,294 - DEBUG Wrapped collection in role: hibernate_test.PasswordStandard.siteUserLogins

[java] done with add to hibernate, sleeping...
[java] AWAKEN!!!
[java] at this time, a direct query shows 2 records in the password standards table
[java] 18:01:31,679 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:31,679 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:31,679 - DEBUG TransactionImpl.getStatus()
[java] 18:01:31,679 - DEBUG status=STATUS_ACTIVE
[java] 18:01:31,679 - DEBUG unable to locate HQL query plan in cache; generating (from PasswordStandard)
[java] 18:01:31,689 - DEBUG parse() - HQL: from hibernate_test.PasswordStandard
[SNIP == HQL PLAN]
[java] 18:01:31,729 - DEBUG throwQueryException() : no errors
[java] 18:01:31,729 - DEBUG HQL param location recognition took 0 mills (from PasswordStandard)
[java] 18:01:31,729 - DEBUG flushing session
[java] 18:01:31,739 - DEBUG processing flush-time cascades
[java] 18:01:31,749 - DEBUG dirty checking collections
[java] 18:01:31,749 - DEBUG Flushing entities and processing referenced collections
[java] 18:01:31,849 - DEBUG Collection found: [hibernate_test.PasswordStandard.tradingPasswords#3], was: [<unreferenced>] (initialized)
[java] 18:01:31,849 - DEBUG Collection found: [hibernate_test.PasswordStandard.siteUserLogins#3], was: [<unreferenced>] (initialized)
[java] 18:01:31,849 - DEBUG Processing unreferenced collections
[java] 18:01:31,849 - DEBUG Scheduling collection removes/(re)creates/updates
[java] 18:01:31,899 - DEBUG Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
[java] 18:01:31,899 - DEBUG Flushed: 2 (re)creations, 0 updates, 0 removals to 2 collections
[java] 18:01:31,899 - DEBUG listing entities:
[java] 18:01:31,930 - DEBUG hibernate_test.PasswordStandard{passwordStdEffectiveDt=03 February 2006, passwordStandardId=3, tradingPasswords=[],

siteUserLogins=[], encodingAlgorithm=fakeEnc, hashAlgorithm=fakeHash}
[java] 18:01:31,930 - DEBUG changes must be flushed to space: TV.PASSWORD_STANDARD
[java] 18:01:31,930 - DEBUG Need to execute flush
[java] 18:01:31,930 - DEBUG executing flush
[java] 18:01:31,930 - DEBUG Inserting entity: [hibernate_test.PasswordStandard#3]
[java] 18:01:31,930 - DEBUG about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[java] 18:01:31,930 - DEBUG opening JDBC connection
[SNIP -- DEBUG INFO FOR INSERT TO DB]
[java] 18:01:32,130 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,130 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:32,130 - DEBUG TransactionImpl.getStatus()
[java] 18:01:32,130 - DEBUG status=STATUS_ACTIVE
[java] 18:01:32,130 - DEBUG aggressively releasing JDBC connection
[java] 18:01:32,130 - DEBUG closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 18:01:32,140 - DEBUG post flush
[java] 18:01:32,150 - DEBUG located HQL query plan in cache (from PasswordStandard)
[java] 18:01:32,150 - DEBUG flushing session
[java] 18:01:32,150 - DEBUG processing flush-time cascades
[java] 18:01:32,150 - DEBUG dirty checking collections
[java] 18:01:32,150 - DEBUG Flushing entities and processing referenced collections
[java] 18:01:32,150 - DEBUG Collection found: [hibernate_test.PasswordStandard.tradingPasswords#3], was:

[hibernate_test.PasswordStandard.tradingPasswords#3] (initialized)
[java] 18:01:32,150 - DEBUG Collection found: [hibernate_test.PasswordStandard.siteUserLogins#3], was:

[hibernate_test.PasswordStandard.siteUserLogins#3] (initialized)
[java] 18:01:32,150 - DEBUG Processing unreferenced collections
[java] 18:01:32,150 - DEBUG Scheduling collection removes/(re)creates/updates
[java] 18:01:32,150 - DEBUG Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 18:01:32,150 - DEBUG Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
[java] 18:01:32,150 - DEBUG listing entities:
[java] 18:01:32,150 - DEBUG hibernate_test.PasswordStandard{passwordStdEffectiveDt=03 February 2006, passwordStandardId=3, tradingPasswords=[],

siteUserLogins=[], encodingAlgorithm=fakeEnc, hashAlgorithm=fakeHash}
[java] 18:01:32,150 - DEBUG Dont need to execute flush
[java] 18:01:32,150 - DEBUG find: from PasswordStandard
[java] 18:01:32,150 - DEBUG named parameters: {}
[java] 18:01:32,150 - DEBUG about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[SNIP -- DEBUG FOR HQL QUERY FOR ALL OBJECTS]
[java] 18:01:32,250 - DEBUG result set row: 0
[java] 18:01:32,250 - DEBUG returning '1' as column: PASSWORD1_28_
[java] 18:01:32,250 - DEBUG result row: EntityKey[hibernate_test.PasswordStandard#1]
[java] 18:01:32,250 - DEBUG Initializing object from ResultSet: [hibernate_test.PasswordStandard#1]
[java] 18:01:32,260 - DEBUG Hydrating entity: [hibernate_test.PasswordStandard#1]
[java] 18:01:32,270 - DEBUG returning 'MD5' as column: HASH2_28_
[java] 18:01:32,270 - DEBUG returning 'BASE16' as column: ENCODING3_28_
[java] 18:01:32,270 - DEBUG returning '01 January 1900' as column: PASSWORD4_28_
[java] 18:01:32,270 - DEBUG result set row: 1
[java] 18:01:32,270 - DEBUG returning '2' as column: PASSWORD1_28_
[java] 18:01:32,270 - DEBUG result row: EntityKey[hibernate_test.PasswordStandard#2]
[java] 18:01:32,270 - DEBUG Initializing object from ResultSet: [hibernate_test.PasswordStandard#2]
[java] 18:01:32,270 - DEBUG Hydrating entity: [hibernate_test.PasswordStandard#2]
[java] 18:01:32,270 - DEBUG returning 'SHA-512' as column: HASH2_28_
[java] 18:01:32,270 - DEBUG returning 'BASE64' as column: ENCODING3_28_
[java] 18:01:32,270 - DEBUG returning '17 August 2005' as column: PASSWORD4_28_
[java] 18:01:32,270 - DEBUG result set row: 2
[java] 18:01:32,270 - DEBUG returning '3' as column: PASSWORD1_28_
[java] 18:01:32,270 - DEBUG result row: EntityKey[hibernate_test.PasswordStandard#3]
[java] 18:01:32,270 - DEBUG done processing result set (3 rows)
[java] 18:01:32,270 - DEBUG about to close ResultSet (open ResultSets: 1, globally: 1)
[java] 18:01:32,270 - DEBUG about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 18:01:32,270 - DEBUG closing statement
[java] 18:01:32,270 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,270 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:32,270 - DEBUG TransactionImpl.getStatus()
[java] 18:01:32,270 - DEBUG status=STATUS_ACTIVE
[java] 18:01:32,270 - DEBUG aggressively releasing JDBC connection
[java] 18:01:32,270 - DEBUG closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 18:01:32,280 - DEBUG total objects hydrated: 2
[java] 18:01:32,280 - DEBUG resolving associations for [hibernate_test.PasswordStandard#1]
[java] 18:01:32,300 - DEBUG creating collection wrapper:[hibernate_test.PasswordStandard.tradingPasswords#1]
[java] 18:01:32,300 - DEBUG creating collection wrapper:[hibernate_test.PasswordStandard.siteUserLogins#1]
[java] 18:01:32,300 - DEBUG done materializing entity [hibernate_test.PasswordStandard#1]
[java] 18:01:32,300 - DEBUG resolving associations for [hibernate_test.PasswordStandard#2]
[java] 18:01:32,300 - DEBUG creating collection wrapper:[hibernate_test.PasswordStandard.tradingPasswords#2]
[java] 18:01:32,300 - DEBUG creating collection wrapper:[hibernate_test.PasswordStandard.siteUserLogins#2]
[java] 18:01:32,300 - DEBUG done materializing entity [hibernate_test.PasswordStandard#2]
[java] 18:01:32,300 - DEBUG initializing non-lazy collections
[java] 18:01:32,300 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,300 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:32,300 - DEBUG TransactionImpl.getStatus()
[java] 18:01:32,300 - DEBUG status=STATUS_ACTIVE
[java] at this time, a HQL query shows 3 records in the password standards table
[java] ID[1] = 1
[java] Hash[1] = MD5
[java] Encoding[1] = BASE16
[java] Effective Date[1] = 1900-01-01
[java] ID[2] = 2
[java] Hash[2] = SHA-512
[java] Encoding[2] = BASE64
[java] java.lang.Exception: force rollback exception
[java] at Hello.main(Hello.java:99)
[java] Effective Date[2] = 2005-08-17
[java] ID[3] = 3
[java] Hash[3] = fakeHash
[java] Encoding[3] = fakeEnc
[java] Effective Date[3] = Fri Feb 03 18:41:49 PST 2006
[java] >>attempting to force a rollback by way of Exception
[java] ERROR: force rollback exception
[java] trying rollback
[java] 18:01:32,310 - DEBUG Current.setRollbackOnly()
[java] 18:01:32,310 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,310 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:32,310 - DEBUG TransactionImpl.setRollbackOnly(tx= bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 18:01:32,310 - DEBUG status=STATUS_ACTIVE
[java] 18:01:32,310 - DEBUG Current.rollback()
[java] 18:01:32,310 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,310 - DEBUG Transaction ret= bb14:38:0:01ead731021646dd4c...78fc01:
[java] 18:01:32,310 - DEBUG threadTx.set= null
[java] 18:01:32,310 - DEBUG TransactionImpl.rollback(tx= bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 18:01:32,310 - DEBUG status=STATUS_MARKED_ROLLBACK
[java] 18:01:32,310 - DEBUG TransactionImpl.doDetach flag= TMSUCCESS
[java] 18:01:32,310 - DEBUG number of enlisted= 0
[java] 18:01:32,310 - DEBUG transaction rolling back
[java] 18:01:32,310 - DEBUG doBeforeCompletion committing= false
[java] 18:01:32,310 - DEBUG unset timer for tx (timer=org.objectweb.jotm.TimerEvent@a6d51e, tx=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 18:01:32,310 - DEBUG TimerEvent(bb14:38:0:01ead731021646dd4c...78fc01:).unset
[java] 18:01:32,310 - DEBUG SubCoordinator.doRollback()
[java] 18:01:32,310 - DEBUG doAfterCompletion()
[java] 18:01:32,310 - DEBUG sychronization list size= 2
[java] 18:01:32,310 - DEBUG Synchronization sync= org.hibernate.transaction.CacheSynchronization
[java] 18:01:32,310 - DEBUG sync.afterCompletion status= STATUS_ROLLEDBACK
[java] 18:01:32,310 - DEBUG transaction after completion callback, status: 4
[java] 18:01:32,310 - DEBUG after transaction completion
[java] 18:01:32,310 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,310 - DEBUG Transaction ret= null
[java] 18:01:32,310 - DEBUG after transaction completion
[java] 18:01:32,310 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,310 - DEBUG Transaction ret= null
[java] 18:01:32,310 - DEBUG no active transaction, could not register Synchronization
[java] 18:01:32,310 - DEBUG threadTx.get= java.lang.ThreadLocal@16df84b
[java] 18:01:32,310 - DEBUG Transaction ret= null
[java] 18:01:32,310 - DEBUG no active transaction, could not register Synchronization
[java] 18:01:32,310 - DEBUG automatically closing session
[java] 18:01:32,310 - DEBUG automatically closing session
[java] 18:01:32,310 - DEBUG closing session
[java] 18:01:32,310 - DEBUG connection already null in cleanup : no action
[java] 18:01:32,310 - DEBUG Synchronization sync= org.hibernate.context.JTASessionContext$CleanupSynch@1a4181c
[java] 18:01:32,310 - DEBUG sync.afterCompletion status= STATUS_ROLLEDBACK
[java] 18:01:32,320 - DEBUG remove tx from xid (xid=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 18:01:32,320 - DEBUG SubCoordinator unexported [subcoord=org.objectweb.jotm.SubCoordinator@1aa0a15]
[java] 18:01:32,320 - DEBUG remove tx from xid (xid=bb14:38:0:01ead731021646dd4c...78fc01:)
[java] 18:01:32,320 - DEBUG reset timeout= 60
[java] rollback complete
[java] 18:01:32,320 - INFO stop JOTM
[java] 18:01:32,320 - DEBUG threadTx.set= null
[java] 18:01:32,320 - DEBUG TransactionFactory unexported
BUILD SUCCESSFUL
Total time: 1 minute

















The class that is not rolling back





relevant supporting java classes









Hibernate Configuration





[/list]

So, after messing around, I figured out what was going on. It was sort of two problems.

First, the getConnection() method of the particular XA datasource I used returns just that -- a java.sql.Connection. Rolling back a UserTransaction for a plain vanilla Connection instance does absolutely nothing if the connection is not bound to the UserTransaction in the first place.

Hibernate calls getConnection() (the datasource connection manager does). What I had to do was write a custom connection manager that calls XADatasource.getXAConnection().getConnection().

That was the first lesson. XAConnection is not true physical connection.

Then, I looked at how I was working with my datasource. I had ignored the example in the JOTM package for pooling, because I saw 'enhydra' in package of the StandardXADatasource class. I was under the mistaken impression that Enhydra was a server, and that this would only work in a server. Looking at the code (in XAPool), I saw that any pool of connections can be made into an XADatasource using this class. So, I tried that, and it worked just fine. That class has a method by which you can associate the JOTM TX Manager with the datasource, and rollbacks to your UT will rollback DB activity.

Another lession was that a UserTransaction is not a transaction in the DB sense. It is an interface to transactions (plural). To use one UT in a suite of unit tests, you have to make sure you're getting either a commit or rollback in every case, or else you can run into situations where you are trying to create nested transactions.

Also, for hibernate to even work in this mode, you MUST call tx.begin(). You cannot just have a UserTransaction sitting somewhere "unused" (I was hoping to use begin/commit/rollback only for write operations, and not use the transaction at all for read operations. No such luck.

JOTM sometimes will continue running, so at the end of my test suite I had to add a System.exit call. Sometimes a thrown exception will cause this to happen, even if there's a rollback() in the finally clause for the method.

Finally, XAPool includes an Oracle-specific implementation of XADatasource, but it does not work with the 10g drivers (and it hasn't been updated in over 2 years), so that's why I had to go with the more abstract StandardXADatasource.

I hope this info speeds up development for other folks who encounter similar issues.