Closing ongoing preparedStatement and connection

freeva · **Joined:** Fri Dec 02, 2005 9:55 am **Posts:** 2

Hibernate version: 3.0.5
database: Oracle 9.2.0.4.0
Appserver: WLS 8.1 SP4

Working with CMT session beans and got a problem with hibernate closing an ongoing nested prepared statement(and the connection). Se log and cfg.xml below. This is happening when we use a JNDI XA datasource/connection from oracle.jdbc.xa.client.OracleXADataSource. But if we use the thin non XA driver oracle.jdbc.driver.OracleDriver it works fine.

It seems to be a similar(or in area of) problem of bug HHH-876, http://opensource2.atlassian.com/projects/hibernate/browse/HHH-876 . This bug is solved in 3.1 rc1 and issues a problem with method AbstractBatcher.hasOpenResources().

I did some testing with ver. 3.1 rc3 and still have the problem, then I got desperate; I changed the source code in AbstractBatcher.hasOpenResources() to always return true(I said I was desperate…) and then I didn’t got the problem of closing the prepared statement/connection. Looking at the code in AbstractBatcher I noticed that the hashmap statementsToClose that stores ongoing prepared statements does not always store a statement when a statement is created. So AbstractBatcher.hasOpenResources() returns false even if we have a ongoing statement. Closing statements/connection is also depending on what isAggressiveRelease() method is returning.

But in a CMT environment you are supposed to have the property hibernate.connection.release_mode to after_statement or auto. And again looking at the source code in method isAggressiveRelease() I don´t see much difference regardless of the release_mode settings.

Code:

public void afterStatement() {
  if ( isAggressiveRelease() ) {
    if ( batcher.hasOpenResources() ) {
      log.info( "Skipping aggresive-release due to open resources on batcher" );
    }
    else {
      aggressiveRelease();
    }
  }
}

public boolean isAggressiveRelease() {
  boolean inAutoCommitState;
  try {
    inAutoCommitState = !callback.isTransactionInProgress() && isAutoCommit();
  }
  catch( SQLException e ) {
    // assume we are in an auto-commit state
    inAutoCommitState = true;
  }
  // release connections
  return releaseMode == ConnectionReleaseMode.AFTER_STATEMENT  ||
          ( releaseMode == ConnectionReleaseMode.AFTER_TRANSACTION && inAutoCommitState );
}

Hibernate.cfg.xml:

Code:

Mapping documents:
<property name="hibernate.jndi.class">weblogic.jndi.WLInitialContextFactory</property>
    
<!-- Database options (Oracle) -->
<property name="hibernate.connection.datasource">jdbc/ihanDS</property>
<property name="hibernate.dialect">org.hibernate.dialect.Oracle9Dialect</property>
<propertyname="hibernate.query.factory_class">org.hibernate.hql.classic.ClassicQueryTranslatorFactory</property>
   
<!-- Transaction options -->
<property name="hibernate.transaction.factory_class">org.hibernate.transaction.CMTTransactionFactory</property>
<propertyname="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.WeblogicTransactionManagerLookup</property>
<propertyname="hibernate.transaction.flush_before_completion">true</property>
<property name="hibernate.transaction.auto_close_session">true</property> 
<property name="hibernate.connection.release_mode">auto</property>    
<!-- Query substitutions, makes HQL more readable -->
<property name="hibernate.query.substitutions">true 1, false 0</property>  
<!-- Debuggning options -->
<property name="show_sql">true</property>
<!-- cache options-->
<property name="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
<property name="hibernate.cache.use_query_cache">false</property>

(Error) Log:

Code:

Full stack trace of any exception that occurs:
DEBUG hibernate.jdbc.ConnectionManager - opening JDBC connection
DEBUG org.hibernate.SQL - insert into HDOM_INSKRIVNING_VERSION_MAP (KEY_INSKRIVNING, NUMBER_PERSPECTIVE, dagboksnr, enligtIfr, version_nr, inskrivningsstatus, GALLANDEBESLUT_CLASS, GALLANDEBESLUT_ID, KEY_AFFARSHANDELSE) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
DEBUG hibernate.jdbc.AbstractBatcher - preparing statement
DEBUG hibernate.type.LongType - binding '30' to parameter: 1
… etc …
DEBUG hibernate.type.LongType - binding null to parameter: 6
DEBUG hibernate.impl.SessionImpl - initializing proxy: [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG event.def.DefaultLoadEventListener - attempting to resolve: [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG event.def.DefaultLoadEventListener - object not resolved in any cache: [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG persister.entity.BasicEntityPersister - Materializing entity: [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG hibernate.loader.Loader - loading entity: [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 1, globally: 3)
DEBUG org.hibernate.SQL - select gallandebe0_.KEY_GALLANDEBESLUTEXTERN as KEY1_0_, gallandebe0_.VER as VER28_0_, gallandebe0_.DNR_IM as DNR3_28_0_, gallandebe0_.DNR_AR as DNR4_28_0_, gallandebe0_.DNR_NR as DNR5_28_0_, gallandebe0_.aktnr as aktnr28_0_, gallandebe0_.dagboksnr as dagboksnr28_0_, gallandebe0_.inskrivningsdag as inskrivn8_28_0_, gallandebe0_.beslutstyp as beslutstyp28_0_ from HDOM_GALLANDEBESLUTEXTERN gallandebe0_ where gallandebe0_.KEY_GALLANDEBESLUTEXTERN=?
DEBUG hibernate.jdbc.AbstractBatcher - preparing statement
DEBUG hibernate.type.LongType - binding '24' to parameter: 1
… etc …
DEBUG hibernate.loader.Loader - done processing result set (1 rows)
DEBUG hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 2, globally: 4)
DEBUG hibernate.jdbc.AbstractBatcher - closing statement
DEBUG hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
DEBUG hibernate.jdbc.ConnectionManager - closing JDBC connection [ (open PreparedStatements: 1, globally: 3) (open ResultSets: 0, globally: 0)]
DEBUG hibernate.loader.Loader - total objects hydrated: 1
DEBUG hibernate.engine.TwoPhaseLoad - resolving associations for [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG event.def.DefaultLoadEventListener - loading entity: [se.lantmateriet.ir.ihan.bo.domain.konstant.KonstantDO#70]
DEBUG event.def.DefaultLoadEventListener - entity found in session cache
DEBUG hibernate.engine.TwoPhaseLoad - done materializing entity [se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO#24]
DEBUG hibernate.engine.PersistenceContext - initializing non-lazy collections
DEBUG hibernate.loader.Loader - done entity load
DEBUG hibernate.type.StringType - binding 'se.lantmateriet.ir.ihan.bo.domain.GallandeBeslutExternDO' to parameter: 7
DEBUG hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 3)
DEBUG hibernate.jdbc.AbstractBatcher - closing statement
DEBUG hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
DEBUG hibernate.util.JDBCExceptionReporter - could not insert collection rows: [se.lantmateriet.ir.ihan.bo.domain.InskrivningDO.inskrivningDOVersionMap#30] [insert into HDOM_INSKRIVNING_VERSION_MAP (KEY_INSKRIVNING, NUMBER_PERSPECTIVE, dagboksnr, enligtIfr, version_nr, inskrivningsstatus, GALLANDEBESLUT_CLASS, GALLANDEBESLUT_ID, KEY_AFFARSHANDELSE) values (?, ?, ?, ?, ?, ?, ?, ?, ?)]
java.sql.SQLException: Connection closed
 at weblogic.jdbc.wrapper.JTAConnection.getXAConn(JTAConnection.java:193)
 at weblogic.jdbc.wrapper.JTAConnection.checkConnection(JTAConnection.java:84)
 at weblogic.jdbc.wrapper.Statement.checkStatement(Statement.java:234)
 at weblogic.jdbc.wrapper.PreparedStatement.setString(PreparedStatement.java:636)
 at org.hibernate.type.StringType.set(StringType.java:24)
 at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:62)
 at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:44)
 at org.hibernate.type.MetaType.nullSafeSet(MetaType.java:73)
 at org.hibernate.type.AnyType.nullSafeSet(AnyType.java:135)
 at org.hibernate.type.AnyType.nullSafeSet(AnyType.java:118)
 at org.hibernate.type.ComponentType.nullSafeSet(ComponentType.java:218)
 at org.hibernate.persister.collection.AbstractCollectionPersister.writeElement(AbstractCollectionPersister.java:652)
 at org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(AbstractCollectionPersister.java:1071)
 at org.hibernate.action.CollectionUpdateAction.execute(CollectionUpdateAction.java:48)
 at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:239)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:223)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:139)
 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:274)
 at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:48)
 at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:711)
 at org.hibernate.impl.SessionImpl.prepareQueries(SessionImpl.java:895)
 at org.hibernate.impl.SessionImpl.getQueries(SessionImpl.java:885)
 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:834)
 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
 at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:603)
 at se.lantmateriet.ir.ihan.bo.hibernate.HibernateRepository.findFastighetByFnr(HibernateRepository.java:78)
 at se.lantmateriet.ir.ihan.bo.assembler.FastighetAssembler.updateDO(FastighetAssembler.java:105)
 at se.lantmateriet.ir.ihan.bo.assembler.LagfartAssembler.updateLagfartDO(LagfartAssembler.java:98)
 at se.lantmateriet.ir.ihan.bo.assembler.LagfartAssembler.updateDO(LagfartAssembler.java:83)
 at se.lantmateriet.ir.ihan.bo.assembler.FastighetAssembler.updateFastighetDO(FastighetAssembler.java:171)
 at se.lantmateriet.ir.ihan.bo.assembler.FastighetAssembler.updateDO(FastighetAssembler.java:120)
 at se.lantmateriet.ir.ihan.bo.assembler.FastighetArendeAssembler.updateFastighetArendeDO(FastighetArendeAssembler.java:119)
 at se.lantmateriet.ir.ihan.bo.assembler.FastighetArendeAssembler.updateDO(FastighetArendeAssembler.java:98)
 at se.lantmateriet.ir.ihan.bo.assembler.AtgardAssembler.updateAtgardDO(AtgardAssembler.java:214)
 at se.lantmateriet.ir.ihan.bo.assembler.AtgardAssembler.updateDO(AtgardAssembler.java:123)
 at se.lantmateriet.ir.ihan.bo.assembler.InskrivningsarendeAssembler.updateInskrivningsarendeDO(InskrivningsarendeAssembler.java:118)
 at se.lantmateriet.ir.ihan.bo.assembler.InskrivningsarendeAssembler.updateDO(InskrivningsarendeAssembler.java:83)
 at se.lantmateriet.ir.ihan.bo.assembler.ArendeAssembler.updateDO(ArendeAssembler.java:52)
 at se.lantmateriet.ir.ihan.bo.assembler.ImArendeAssembler.updateImArendeDO(ImArendeAssembler.java:226)
 at se.lantmateriet.ir.ihan.bo.assembler.ImArendeAssembler.updateDO(ImArendeAssembler.java:135)
 at se.lantmateriet.ir.ihan.bo.assembler.AssemblerFacade.updateImArende(AssemblerFacade.java:67)
 at se.lantmateriet.ir.ihan.bs.imarendeservice.ImArendeService.sparaImArende(ImArendeService.java:105)
 at se.lantmateriet.ir.ihan.bs.imarendeservice.ejb.ImArendeServiceBean.sparaImArende(ImArendeServiceBean.java:50)
 at se.lantmateriet.ir.ihan.bs.imarendeservice.ejb.IhanIMarendeService_s1qjr0_EOImpl.sparaImArende(IhanIMarendeService_s1qjr0_EOImpl.java:254)
 at se.lantmateriet.ir.ihan.bs.imarendeservice.ejb.IhanIMarendeService_s1qjr0_EOImpl_WLSkel.invoke(Unknown Source)
 at weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:477)
 at weblogic.rmi.cluster.ReplicaAwareServerRef.invoke(ReplicaAwareServerRef.java:108)
 at weblogic.rmi.internal.BasicServerRef$1.run(BasicServerRef.java:420)
 at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:147)
 at weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:415)
 at weblogic.rmi.internal.BasicExecuteRequest.execute(BasicExecuteRequest.java:30)
 at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
 at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)
WARN  hibernate.util.JDBCExceptionReporter - SQL Error: 0, SQLState: null
ERROR hibernate.util.JDBCExceptionReporter - Connection closed

steve · **Posted:** Fri Dec 02, 2005 12:14 pm

What is the use-case/application-code causing this?

freeva · **Joined:** Fri Dec 02, 2005 9:55 am **Posts:** 2

The application receives a graph of Data Transfer Objects, converts it to a graph of Domain Objects and persists the changes made (pretty much according to the Data Transfer Object pattern in PoEAA. In order to cope with circular references in the graph, each new object found while parsing the graph is saved immediatley so that a unique primary key is created for every item. To accomplish that we have declared a lot of constraints to be DEFERRABLE INITIALLY DEFERRED.

Perhaps the use of deferred constraints could be a problem in conjuction with the XA driver? Please note that the code works fine when using the thin Oracle driver. Is there anything particular that has to be added to the Hibernate configuration when working with deferred constraints?

It seems a bit strange that Hibernates does an aggressiveRelease() even though globalOpenPreparedStatementCount knows that there are more open prepared statements. What could be the reason for that?

steve · **Posted:** Mon Dec 05, 2005 9:14 am

Deferred constraints should not have any effect on this.

AbstractBatcher.globalOpenPreparedStatementCount is static if you notice. It is simply a diagnostic field keeping track of all prepared statements hibernate has open within a particular classloader across all sessions.

At least in looking at the logs, this is exactly the situation addressed by the JIRA issue you mention. There is initially a single PreparedStatement registered for clean-up relating to the insert. In the midst of that insert processing, another PreparedStatement is opened in order to perform some lazy-loading; this one is also registered for clean-up. So at that point, the batcher has two PreparedStatements registered for clean-up. This should cause the aggressive release to be short-circuited. Now there was a bug in this logic, but that was exactly the bug fixed by the JIRA case you mentioned.

If you really, truly tried this with 3.1rc3 and still saw the same problem then create a JIRA issue with a small, reproducible test case.