Hibernate Borrowed Connection with EJB3 and JTA in Jboss - insertion/updating happen before completing session bean method (tx attribute Required)

• I just found an Issue in an application which use Hibernate with EJB3 and JTA in Jboss application server.

Story begins here :

Imagine there is a SessionBean called MysteryBean with two methods called correct1() and wrong1(), each method do the same thing, inserting an entity called Entity.

primary key (id) is generated through custom sequence generator class. Below describe the piece of code in Custom ID generator class.

At front end (Servlet) , it called both methods, one after another through local ejb reference.

//method calling at front-end

here is the hibernate configuration for JTA

Mystery :

After executing method correct1 () entity got inserted in to DB , just after method was completed as we expected, where as in wrong1() method entity got inserted before completing the method which means at dao layer. Also this is a random behavior.

Note :
We are maintaining same hibernate Session through out the flow, which means we created hibernate Session just before executing correct1() method and close it (same hibernate Session) just after executing wrong1() method from front-end. The purpose of this is to follow open session view anti pattern.

Solution :

There are couple of solutions for this miss behavior.

1. Closing connection at finally clause.

2. Use a batcher instead of jdbc connection directly.

Statement st = sessionImplementor.getBatcher().prepareSelectStatement();

and close batcher statements in the finally clause.

sessionImplementor.getBatcher().closeStatements();

3 Or else we can use hibernate default sequence generator.

• But the challenge is finding the reason for this miss behavior.

Reason :


After debugging deep into both Hibernate and jboss-as-connector api, noticed that Hibernate session itself populate jdbc connection (wrap  T4CConnection.java in ojdbc14.jar as WrappedConnectionJDK5.java in jboss api) and use that connection to execute SQL queries. All the jdbc connections maintain withing the Hibernate Session's JDBCContext using ConnectionManager.  


Little bit explanation about JTA and JDBC connection management with hibernate. 


Hibernate configuration for JTA   


hibernate.transaction.factory_class = org.hibernate.transaction.JTATransactionFactory
hibernate.transaction.manager_lookup_class = org.hibernate.transaction.JBossTransactionManagerLookup


When we configured hibernate transaction manager to JTA Hibernate Session's JDBC transaction managed by JTA, which means JDBC connection's AUTO committing become disable (By default AUTO commit true) and JTA responsible to commit all the JDBC transactions.  


With a JTA configuration, Hibernate is even more aggressive: a   connection is obtained and used for only a single SQL statement and then is immediately returned to the managed connection pool. The application server guarantees that it will hand out the same connection during the same transaction, when it’s needed again for another SQL statement.
(Java Persistence With Hibernate – page 445)   


Note: 
In here connection release mode is AFTER_STATEMENT   


This is not quite right always, there is an exceptional case. When we create a Borrowed Connection, Hibernate doesn't manage borrowed connection by itself, which means it's a programmer responsibility.
If we open a borrowed connection it's our responsibility to close it as well. Also in a borrowed connection , AUTO commit is enabled.  


Some facts :   

http://www.harezmi.com.tr/weird-connection-problems-with-spring-and-hibernate/?lang=en   
http://forum.springsource.org/showthread.php?63914-HibernateJpaDialect-doesn%92t-release-borrowed-connection-after-TX-completion   
http://stackoverflow.com/questions/3526556/session-connection-deprecated-on-hibernate   


Back to our Story :   


Story begins with correct1() method, When it try to generate Id for the first time it use borrowed connection and because it's not closed from application the borrowed connection remain even after transaction completed.  


So how is correct1() method getting success as we expected (flush data into DB after transaction complete) ?   


Since Hibernate follow kind of event driven programming techniques , Hibernate session already aware of which connection to obtain before execute generator class code.  


In Hibernate Connection Manager Class there are two types of connections. Both these connections may point to the same jdbc Connection in the pool or else to different connections.
private   transient Connection connection;
private   transient Connection borrowedConnection;  


below display the logs used to inspect JDBC connection status
------  private transient   Connection connection;  -----------


12:22:36,308 INFO [STDOUT] ##################### Client Started #####################  
12:22:58,905 INFO [STDOUT] ##################### Correct 1 Started #####################  
12:23:00,312 DEBUG [JTATransaction] Looking for UserTransaction under: UserTransaction  
12:23:00,312 DEBUG [JTATransaction] Obtained UserTransaction  
12:23:00,312 DEBUG [JDBCContext] successfully registered Synchronization  
12:23:07,073 DEBUG [AbstractSaveEventListener] transient instance of: com.xxx.domain.Entity  
12:23:07,074 DEBUG [DefaultSaveOrUpdateEventListener] saving transient instance  
In the class generate() method, before calling sessionImplementor.connection();  
12:23:23,127 INFO [STDOUT] ===================== No borrowed connection acquired ==================  
12:23:23,911 INFO [STDOUT] Value of privateKey: null  
12:23:25,071 INFO [STDOUT] ===================== Not connected ==================  
12:23:28,543 DEBUG [ConnectionManager] opening JDBC connection  
12:25:01,237 DEBUG [AbstractSaveEventListener] generated identifier: 141308, using strategy: xxx.persistence.hibernate.IdGenerator  
In the HibernateDAO.java class saveOrUpdate() method, before calling  session.flush();  
12:25:01,237 DEBUG [AbstractSaveEventListener] saving [xxx.domain.Entity#141308]  
12:25:07,136 INFO [STDOUT] ================= already have a borrowed connection in dao ================  
12:25:07,136 INFO [STDOUT] Value of privateKey: org.jboss.resource.adapter.jdbc.jdk5.WrappedConnectionJDK5@4d46ac58  
12:25:07,136 INFO [STDOUT] ==================== Autocommit in connection ================false  
12:25:07,136 INFO [STDOUT] ==================== Autocommit in connection manager================false


in here Auto commit status taken from isJdbcAutoCommit() method in org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection class   


boolean isJdbcAutoCommit()   
 {  
    return inManagedTransaction ? false : jdbcAutoCommit;  


 }  


So if the inManagedTransaction = true, the JdbcAutoCommit will be false;

• whole story begins from ------------ > 12:23:28,543 DEBUG [ConnectionManager] opening JDBC connection

which means, after calling org.hibernate.jdbc.ConnectionManager.openConnection() method by sessionImplementor.connection() method.

• Debug stack trace (tx_begin - screen shot) has attached with this document, according to that , begin() method make the JDBC connection auto commit disable (AUTO commit false) and inManagedTransaction to true.

• after calling commit() (tx_commit- screen shot) method,  connection become out of synch with managed transaction.
  
  

(begin() and commit() methods in org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionLocalManagedConnection)   


correct1() method runs in JTA transaction context and jdbc connection related to it’s Hibernate Session bind to same transaction context and when Session.flush() method called data will not be flushed into DB since AUTO commit is false.


Only after transaction completed ( correct1() method completed) java.sql.Connection.commit() method will be called by JTA manager. Then only data will flush into DB.


Then why is wrong1() getting work in an unexpected (flush data into DB after Session.flush() called but before transaction complete)  manner?  


Let’s starting with logs.  


13:36:23,027 INFO  [STDOUT] #####################Correct 1 end #####################  
13:36:23,027 DEBUG [CacheSynchronization] transaction before completion callback  
13:36:23,027 DEBUG [JDBCContext] before transaction completion 
13:36:23,027 DEBUG [SessionImpl] before transaction completion  
13:37:14,721 DEBUG [CacheSynchronization] transaction after completion callback, status: 3  
13:37:14,721 DEBUG [JDBCContext] after transaction completion  
13:37:14,721 DEBUG [SessionImpl] after transaction completion  
13:37:24,918 INFO  [STDOUT] ##################### wrong 1 Started #####################  
13:37:30,823 DEBUG [JTATransaction] Looking for UserTransaction under: UserTransaction  
13:37:30,823 DEBUG [JTATransaction] Obtained UserTransaction  
13:37:30,823 DEBUG [JDBCContext] successfully registered Synchronization  
13:37:32,263 DEBUG [AbstractSaveEventListener] transient instance of: xxx.domain.Entity  
13:37:32,263 DEBUG [DefaultSaveOrUpdateEventListener] saving transient instance  
In the IdGenerator.java class generate() method, before calling sessionImplementor.connection();  
13:37:33,159 INFO  [STDOUT]  ==================== already have a borrowed connection ================  
13:37:33,159 INFO  [STDOUT] Value of privateKey: org.jboss.resource.adapter.jdbc.jdk5.WrappedConnectionJDK5@239fb845  
13:37:33,159 INFO  [STDOUT]  =============== Autocommit in connection ================true  
13:37:33,159 INFO  [STDOUT]  ===============Autocommit in connection manager================true  
13:37:33,224 DEBUG [AbstractSaveEventListener] generated identifier: 141342, using strategy: xxx.persistence.hibernate.IdGenerator  
In the HibernateDAO.java class saveOrUpdate() method, before calling  session.flush();  
13:37:33,224 DEBUG [AbstractSaveEventListener] saving [xxx.domain.Entity#141342]  
13:37:33,919 INFO  [STDOUT]  =================already have a borrowed connection in dao ================  
13:37:33,919 INFO  [STDOUT] Value of privateKey: org.jboss.resource.adapter.jdbc.jdk5.WrappedConnectionJDK5@239fb845  
13:37:33,919 INFO  [STDOUT]  ==================== Autocommit in connection ================true  
13:37:33,919 INFO  [STDOUT]  ==================== Autocommit in connection manager===============true  
13:37:33,919 DEBUG [AbstractFlushingEventListener] flushing session  


Note:   


According to the logs, Hibernate Session is already obtained a connection through org.hibernate.jdbc.ConnectionManager  (which is previously created borrowed connection and since we don’t close, it remains until Session.close() method called by front-end)  and because of that no need to call org.hibernate.jdbc.ConnectionManager.openConnection() method. As a result of that Hibernate Session wont call org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionLocalManagedConnection.begin() method and existing JDBC connection stay with AUTO commit True (default value). When Session.flush() got called , since AUTO commit in True status no need to call  java.sql.Connection.commit() to flush data into DB. This is why in wrong1() method behave in an unexpected way.

This behavior is also not guaranteed which means this is a random behavior. For example, when executing wrong1() Hibernate session may  not populated with previously created borrowed connection, at that point it will work same as correct1() method as we expected.  


So what happen after closing Borrowed connection ?   


Since there is no any borrowed connection to populate with Hibernate Session, wrong1() method execute same as correct1() method (You can see same logs which has in correct1() method).


Conclusion :


Even with managed transaction context , Hibernate borrowed connection not managed by hibernate itself, It's programmer responsibility to managed borrowed connection.