Hibernate version: 3.0.5

Hi Hibernate team, I need to seek your expert advice again ;)

I am running JBoss 4.0.2. And the connection pool's max size is 20. The database is PostgreSQL 8.

I have a simple session bean method, login():

public void login(javax.security.auth.login.LoginContext lc) throws LoginException {
lc.login();
}

which is called by a WebWork action class, which itself is called by a JSP page. The WebWork action class also figures out which login module it needs to use, sets it in the LoginContext before calling the session bean. The login module uses Hibernate to connect to the database to verify the username and password.

The first time I tried to log in with a bad username/password combination, and everything seemed to work as expected:

19:04:58,196 INFO [STDOUT] username: p
19:04:58,196 INFO [STDOUT] password: p
19:04:58,321 DEBUG [JDBCContext] successfully registered Synchronization
19:04:58,321 DEBUG [JDBCContext] successfully registered Synchronization
19:04:58,383 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:04:58,383 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:04:58,383 DEBUG [ConnectionManager] opening JDBC connection
19:04:58,383 DEBUG [ConnectionManager] opening JDBC connection
19:04:58,383 INFO [STDOUT] Hibernate: select this_.user_account_id as user1_0_, this_.user_state_id as user2_28_0_, this_.user_role_id as user3_28_0_, this_.is_internal as is4_28_0_, this_.username as username28_0_, this_.user_password asuser6_28_0_, this_.last_signon as last7_28_0_, this_.last_signon_attemp as last8_28_0_, this_.login_attempts as login9_28_0_, this_.last_active as last10_28_0_, this_.last_signoff as last11_28_0_, this_.create_date as create12_28_0_, this_.update_date as update13_28_0_, this_.version as version28_0_ from public.user_account this_ where (lower(this_.username) like ? and lower(this_.user_password) like ?)
19:04:58,383 DEBUG [AbstractBatcher] preparing statement
19:04:58,383 DEBUG [AbstractBatcher] preparing statement
19:04:58,383 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:04:58,383 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:04:58,383 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets:1, globally: 1)
19:04:58,383 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets:1, globally: 1)
19:04:58,383 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:04:58,383 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:04:58,383 DEBUG [AbstractBatcher] closing statement
19:04:58,383 DEBUG [AbstractBatcher] closing statement
19:04:58,383 DEBUG [ConnectionManager] aggressively releasing JDBC connection
19:04:58,383 DEBUG [ConnectionManager] aggressively releasing JDBC connection
19:04:58,383 DEBUG [ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
19:04:58,383 DEBUG [ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
19:04:58,399 DEBUG [JDBCContext] before transaction completion
19:04:58,399 DEBUG [JDBCContext] before transaction completion
19:04:58,399 DEBUG [JDBCContext] after transaction completion
19:04:58,399 DEBUG [JDBCContext] after transaction completion
19:04:58,399 ERROR [LoginAction] Login failed; reason: SecurityException; nested exception is:
javax.security.auth.login.FailedLoginException: Bad username/password combination
19:04:58,399 ERROR [LoginAction] java.rmi.AccessException: SecurityException; nested exception is:
javax.security.auth.login.FailedLoginException: Bad username/password combination

Immediately after this, I tried to login using a correct login/password combination, and once again, it was working as expected:
19:05:28,758 INFO [STDOUT] username: tien
19:05:28,758 INFO [STDOUT] password: tien
19:05:28,758 DEBUG [JDBCContext] successfully registered Synchronization
19:05:28,758 DEBUG [JDBCContext] successfully registered Synchronization
19:05:28,758 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:05:28,758 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:05:28,774 DEBUG [ConnectionManager] opening JDBC connection
19:05:28,774 DEBUG [ConnectionManager] opening JDBC connection
19:05:28,774 INFO [STDOUT] Hibernate: select this_.user_account_id as user1_0_, this_.user_state_id as user2_28_0_, this_.user_role_id as user3_28_0_, this_.is_internal as is4_28_0_, this_.username as username28_0_, this_.user_password asuser6_28_0_, this_.last_signon as last7_28_0_, this_.last_signon_attemp as last8_28_0_, this_.login_attempts as login9_28_0_, this_.last_active as last10_28_0_, this_.last_signoff as last11_28_0_, this_.create_date as create12_28_0_, this_.update_date as update13_28_0_, this_.version as version28_0_ from public.user_account this_ where (lower(this_.username) like ? and lower(this_.user_password) like ?)
19:05:28,774 DEBUG [AbstractBatcher] preparing statement
19:05:28,774 DEBUG [AbstractBatcher] preparing statement
19:05:28,774 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:05:28,774 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:05:28,805 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets:1, globally: 1)
19:05:28,805 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets:1, globally: 1)
19:05:28,805 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:05:28,805 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:05:28,805 DEBUG [AbstractBatcher] closing statement
19:05:28,805 DEBUG [AbstractBatcher] closing statement
19:05:28,805 DEBUG [ConnectionManager] aggressively releasing JDBC connection
19:05:28,805 DEBUG [ConnectionManager] aggressively releasing JDBC connection
19:05:28,805 DEBUG [ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
19:05:28,805 DEBUG [ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
19:05:28,836 DEBUG [JDBCContext] before transaction completion
19:05:28,836 DEBUG [JDBCContext] before transaction completion
19:05:28,836 DEBUG [JDBCContext] after transaction completion
19:05:28,836 DEBUG [JDBCContext] after transaction completion
19:05:28,836 INFO [LoginAction] tien successfully logged in!

Then I tried another bad combination, then Hibernate just could no longer obtain database connection:

19:05:41,430 INFO [STDOUT] username: t
19:05:41,430 INFO [STDOUT] password: t
19:05:41,446 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:05:41,446 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:05:41,461 ERROR [LoginAction] Login failed; reason: SecurityException; nested exception is:
javax.security.auth.login.LoginException: org.hibernate.HibernateException: Not able to obtain connection
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:113)

This seems to be happened randomly--sometimes I can manage to test my log in logic once before it starts to fail, sometimes twice, sometimes three times but never more than that. Once it is unable to obtain connections, subsequent login attempts always fail.

The same code is being exercised the first time, second time, third time and so on. I am using Hibernate with JTA so Hibernate is managing opening/closing connections for me.

I am sure it is something wrong with my configuration somewhere...or that there is something fundementally flawed in my code. My brain is probably fried from looking at this problem for hours and just can't function anymore :D

I apologize if it's a duplicated post.

If there is some document I should be reading, please kindly point me to it. Otherwise, does anyone know or want to take a guess on what the problem is?