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.
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;
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.
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
- 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.
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.