Problem : Dear All,

We are using JBoss3.2.3, Hibernate2.1.4 and mysql4.0.18.
Now our application was at Production.
I assume each hibernate session will get one datasource connection from pool and whenever session is closed the datasource connection will returned to pool. (Please Highlight if my assumption is wrong)
Normally our application is working fine. But some times after closing session, connections are not returning back to Connection Pool and non returned connections are keep growing in 2-3 hrs. So once non-returned connections size was grown to 20+ then the next request(session) is not getting connection from connection pool , it just using the
non-returned connection and we are getting SQL Exception i.e; SQL Error: 0 SQLState: 08S01 (since it is using the old (bad)connection).
I have gone through the forum to check for related queries, but I was unlucky ..

Your help is highly appreciable ..

Note: Connections InUse is growing when multiple requests(sessions) are issued at same time and only one connection(session was closing) was returning back. And once after this scenario normal request connections also not returning back (some times only).

Below I am providing configuration and Exception details .

Thanks in advance,
Kavuri.

Hibernate version: 2.1.4

Mapping documents:

<property name="dialect">net.sf.hibernate.dialect.MySQLDialect</property>
<property name="show_sql">false</property>
<property name="use_outer_join">true</property>
<property name="connection.isolation">4</property>
<property name="transaction.factory_class">net.sf.hibernate.transaction.JTATransactionFactory</property>
<property name="transaction.manager_lookup_class">net.sf.hibernate.transaction.JBossTransactionManagerLookup</property>
<property name="jta.UserTransaction">UserTransaction</property>

Data Source Configuration :

<!-- pooling enhancement -->
<blocking-timeout-millis>500</blocking-timeout-millis>
<idle-timeout-minutes>5</idle-timeout-minutes>
<min-pool-size>10</min-pool-size>
<max-pool-size>50</max-pool-size>
<check-valid-connection-sql>SELECT 1</check-valid-connection-sql>

<!-- MySQL specific enhancement -->
<connection-property name="autoReconnect">true</connection-property>
<connection-property name="autoReconnectForPools">true</connection-property>
<connection-property name="useNewIO">true</connection-property>


Code between sessionFactory.openSession() and session.close():

openSession :
Session s = (Session) session.get();
if (s == null) {
try {
s = sessionFactory.openSession();
session.set(s);
} catch (Exception e) {
throw new HibernateException(e.getMessage());
}
}
// check if session is not connected
if (!s.isConnected()) {
logger.warn("Reconnecting hibernate session...");
s.reconnect();
}
level++;
return s;
closeSession :
public static void closeSession() {
level--;
if (level <= 0) {
Session s = (Session) session.get();
if (s != null && s.isOpen()) {
session.set(null);
try {
s.flush();
s.close();

} catch (HibernateException e) {
logger.warn(e.getMessage());
}
}
}
}

Full stack trace of exception that occurs:

First Session :

2004-09-07 10:24:42,461 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection from pool [InUse/Available/Max]: [1/10/500]
2004-09-07 10:24:52,290 INFO [com.mlifestyle.etud.ejb.session.facade.vim.VIMFacadeBean] Initializing worker....
2004-09-07 10:24:52,792 INFO [com.mlifestyle.etud.ejb.session.facade.vim.VIMWorker] Waiting for response...
2004-09-07 10:24:52,796 INFO
[com.mlifestyle.etud.ejb.session.facade.vim.VIMWorker] isLogonSuccessful()
2004-09-07 10:24:52,796 INFO [com.mlifestyle.etud.ejb.session.facade.vim.VIMWorker] Logon is successful...
2004-09-07 10:24:52,797 INFO [com.mlifestyle.vim.pdu.BalanceEnquiryRequest] pdu:
2004-09-07 10:24:52,797 INFO [com.mlifestyle.etud.ejb.session.facade.vim.VIMWorker] Waiting for response...
2004-09-07 10:25:20,260 INFO
Second Session: (First one was still in the process)
[com.mlifestyle.etud.ejb.session.facade.dealer.salesstaff.SalesStaffFacadeBean] Find all topup record for sales staff : 64751516
Second session was closed, but datasource connection was not returned back.
2004-09-07 10:25:20,261 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@3c03e1
2004-09-07 10:25:20,261 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection from pool [InUse/Available/Max]: [2/10/500]
2004-09-07 10:25:21,182 INFO
Third Session: (Still the first session was in process)
[com.mlifestyle.etud.ejb.session.facade.dealer.owner.OwnerFacadeBean] Find dealer branch data by Dealer Id where dealer id : 00643
2004-09-07 10:25:21,184 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1f622fa
2004-09-07 10:25:21,184 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection from pool [InUse/Available/Max]: [3/10/500]
2004-09-07 10:25:21,191 INFO [com.mlifestyle.etud.ejb.session.facade.dealer.owner.OwnerFacadeBean] Size of dealerBranchList is : 4
2004-09-07 10:25:21,193 INFO [com.mlifestyle.etud.ejb.session.facade.dealer.owner.OwnerFacadeBean] <NEW> Find dealer sales shifts for Dealer: 00643
2004-09-07 10:25:21,200 INFO [com.mlifestyle.etud.ejb.session.facade.dealer.owner.OwnerFacadeBean] <NEW> Find dealer sales staff for Dealer: 00643
2004-09-07 10:25:21,206 INFO [com.mlifestyle.etud.ejb.session.facade.dealer.owner.OwnerFacadeBean] <NEW> Find dealer staff for Dealer: 00643
The last i.e; Third session was closed, but connection was not returned back to pool.
2004-09-07 10:25:22,802 ERROR [com.mlifestyle.etud.ejb.session.facade.vim.VIMFacadeBean] Balance checking error: No response from VICG!
The First session was closed and the datasource connection was returned back. But mean time there is 2 non returned connections ...
2004-09-07 10:25:22,804 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool
2004-09-07 10:25:22,804 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool [InUse/Available/Max]: [2/10/500]

This value(InUse) is keep growing and causing for a connection time out Exception.

2004-09-07 11:34:58,263 WARN [net.sf.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: 08S01
2004-09-07 11:34:58,263 ERROR [net.sf.hibernate.util.JDBCExceptionReporter] Communication link failure: java.net.SocketException, underlying cause: Connection timed out

** BEGIN NESTED EXCEPTION **

java.net.SocketException
MESSAGE: Connection timed out

STACKTRACE:

java.net.SocketException: Connection timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1385)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1532)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1923)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1163)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1272)
at com.mysql.jdbc.Connection.execSQL(Connection.java:2236)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1555)
at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:304)
at net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:87)
at net.sf.hibernate.loader.Loader.getResultSet(Loader.java:800)
at net.sf.hibernate.loader.Loader.doQuery(Loader.java:189)
at net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:133)
at net.sf.hibernate.loader.Loader.loadEntity(Loader.java:836)
at net.sf.hibernate.loader.Loader.loadEntity(Loader.java:856)
at net.sf.hibernate.loader.EntityLoader.load(EntityLoader.java:59)
at net.sf.hibernate.loader.EntityLoader.load(EntityLoader.java:51)
at net.sf.hibernate.persister.EntityPersister.load(EntityPersister.java:419)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2113)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:1987)
at net.sf.hibernate.impl.SessionImpl.get(SessionImpl.java:1923)
at com.mlifestyle.etud.util.ETUDHibernateLoginModule.getUsersPassword(ETUDHibernateLoginModule.java:127)
at org.jboss.security.auth.spi.UsernamePasswordLoginModule.login(UsernamePasswordLoginModule.java:150)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at org.apache.coyote.tomcat4.CoyoteAdapter.service(CoyoteAdapter.java:197)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:781)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:549)
at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:605)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:677)
at java.lang.Thread.run(Thread.java:534)


** END NESTED EXCEPTION **


2004-09-07 11:34:58,267 WARN [net.sf.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: 08S01
2004-09-07 11:34:58,267 ERROR [net.sf.hibernate.util.JDBCExceptionReporter] Communication link failure: java.net.SocketException, underlying cause: Connection timed out

** BEGIN NESTED EXCEPTION **

java.net.SocketException
MESSAGE: Connection timed out

STACKTRACE:

java.net.SocketException: Connection timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1385)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1532)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1923)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1163)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1272)
at com.mysql.jdbc.Connection.execSQL(Connection.java:2236)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1555)
at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:304)

Name and version of the database we are using: MySql 4.0.18 Max

Application Server : JBoss3.2.3

Debug level Hibernate log excerpt:

Is there any thing I confused you all ????