Issue Details (XML | Word | Printable)

Key: HHH-1900
Type: Bug Bug
Status: Open Open
Priority: Critical Critical
Assignee: Unassigned
Reporter: Greg Burcher
Votes: 4
Watchers: 3
Operations

If you were logged in you would be able to see more operations.
Hibernate Core

Prepared Statement closed before executed by AbstractBatcher - similar to HHH-876

Created: 12/Jul/06 03:47 PM   Updated: 10/Feb/09 06:33 AM
Component/s: core
Affects Version/s: 3.1.3
Fix Version/s: None

Time Tracking:
Not Specified

Environment: hibernate 3.1.3, MS SQL Server, Apache DBCP, JSQLConnect


 Description  « Hide
Using Hibernate v3.1.3, I am experiencing symptoms that sound like bug HHH-876. Problem has been intermittent, may be related to timing/latency. Problem happens less frequently when lots of hibernate debug logging is turned on. Using JDBC drivers from jnetdirect, get com.jnetdirect.jsql.JSQLException with message of "The statement is closed".

Failure occurs on a variety of queries, but only occasionally for any given query. Once the problem has occurred for a particular query (prepared statement), problem will occur every time from that point on for that query.

Here is debug trace pattern of successful query:

10:05:40,099 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:05:40,099 DEBUG ConnectionManager:358 - opening JDBC connection
10:05:40,109 DEBUG DBCPConnectionProvider:? - active: 1 (max: 20) idle: 0(max: 20)
Hibernate: select this_.id as id27_0_, this_.language as language27_0_, this_.enabled as enabled27_0_, this_.sourceID as sourceID27_0_, this_.focusQuestion as focusQue5_27_0_, this_.markedFocusQuestion as markedFo6_27_0_ from WebInquiryFocusQuestion this_ where this_.id=? and this_.enabled=? and this_.language=?
10:05:40,109 DEBUG AbstractBatcher:424 - preparing statement
10:05:40,109 DEBUG AbstractBatcher:327 - about to open ResultSet (open ResultSets: 0, globally: 0)
10:05:40,109 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
10:05:40,109 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:05:40,109 DEBUG AbstractBatcher:470 - closing statement
10:05:40,119 DEBUG JDBCContext:213 - after autocommit
10:05:40,119 DEBUG ConnectionManager:341 - aggressively releasing JDBC connection
10:05:40,119 DEBUG ConnectionManager:378 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
10:05:40,119 DEBUG DBCPConnectionProvider:? - active: 0 (max: 20) idle: 1(max: 20)

versus trace when error occurs:

10:05:41,481 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:05:41,481 DEBUG ConnectionManager:358 - opening JDBC connection
10:05:41,481 DEBUG DBCPConnectionProvider:? - active: 1 (max: 20) idle: 0(max: 20)
Hibernate: select this_.id as id27_0_, this_.language as language27_0_, this_.enabled as enabled27_0_, this_.sourceID as sourceID27_0_, this_.focusQuestion as focusQue5_27_0_, this_.markedFocusQuestion as markedFo6_27_0_ from WebInquiryFocusQuestion this_ where this_.id=? and this_.enabled=? and this_.language=?
10:05:41,481 DEBUG AbstractBatcher:424 - preparing statement
10:05:41,481 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:05:41,481 DEBUG AbstractBatcher:470 - closing statement
10:05:41,501 WARN JDBCExceptionReporter:71 - SQL Error: 0, SQLState: null
10:05:41,501 ERROR JDBCExceptionReporter:72 - The statement is closed
10:05:41,511 DEBUG JDBCContext:213 - after autocommit
10:05:41,511 DEBUG ConnectionManager:341 - aggressively releasing JDBC connection
10:05:41,511 DEBUG ConnectionManager:378 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
10:05:41,511 DEBUG DBCPConnectionProvider:? - active: 0 (max: 20) idle: 1(max: 20)
10:05:41,511 DEBUG ConnectionManager:312 - connection already null in cleanup : no action

Partial stack trace:

[0] com.jnetdirect.jsql.JSQLException.makeFromDriverError:70 (in file JSQLException.java)
[1] com.jnetdirect.jsql.JSQLStatement.setParam:1223 (in file JSQLStatement.java)
[2] com.jnetdirect.jsql.JSQLPreparedStatement.setInt:693 (in file JSQLPreparedStatement.java)
[3] org.apache.commons.dbcp.DelegatingPreparedStatement.setInt:116 (in file DelegatingPreparedStatement.java)
[4] org.apache.commons.dbcp.DelegatingPreparedStatement.setInt:116 (in file DelegatingPreparedStatement.java)
[5] org.hibernate.type.IntegerType.set:41 (in file IntegerType.java)
[6] org.hibernate.type.NullableType.nullSafeSet:85 (in file NullableType.java)
[7] org.hibernate.type.NullableType.nullSafeSet:63 (in file NullableType.java)
[8] org.hibernate.loader.Loader.bindPositionalParameters:1514 (in file Loader.java)
[9] org.hibernate.loader.Loader.prepareQueryStatement:1576 (in file Loader.java)
[10] org.hibernate.loader.Loader.doQuery:661 (in file Loader.java)
[11] org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections:224 (in file Loader.java)
[12] org.hibernate.loader.Loader.doList:2145 (in file Loader.java)
[13] org.hibernate.loader.Loader.listIgnoreQueryCache:2029 (in file Loader.java)
[14] org.hibernate.loader.Loader.list:2024 (in file Loader.java)
[15] org.hibernate.loader.criteria.CriteriaLoader.list:94 (in file CriteriaLoader.java)
[16] org.hibernate.impl.SessionImpl.list:1552 (in file SessionImpl.java)
[17] org.hibernate.impl.CriteriaImpl.list:283 (in file CriteriaImpl.java)
[18] org.hibernate.impl.CriteriaImpl.uniqueResult:305 (in file CriteriaImpl.java)

Stack trace will differ depending on which query triggers the problem.

 All   Comments   Work Log   Change History   FishEye      Sort Order: Ascending order - Click to sort in descending order
Nicolas Savois added a comment - 24/Jul/08 11:50 AM
I am facing the exact same problem,

i can't describe it better than what was previously said :

Failure occurs on a variety of queries, but only occasionally for any given query. Once the problem has occurred for a particular query (prepared statement), problem will occur every time from that point on for that query.

I am on different environments though,
hibernate 3.2.6 - spring 2.0.6 - dbcp 1.2.2 - Oracle 10g

partial stacktrace :

java.sql.SQLException: Closed Statement
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146)
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208)
oracle.jdbc.driver.OracleStatement.ensureOpen(OracleStatement.java:3519)
oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3297)
oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3361)
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
org.hibernate.loader.Loader.doQuery(Loader.java:674)
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
org.hibernate.loader.Loader.loadEntity(Loader.java:1860)
org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3049)
org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:399)
org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:98)
org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:836)
org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:66)
org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:150)

I've never been able to reproduce this out of my production environment, which is pretty annoying... I've been loading my development environment with JMeter (a lot !) but with no results...

any fix i missed?

breako added a comment - 21/Aug/08 11:39 AM
Hi Nicolas,
I am experiencing similar issue, any idea for fix.
Thanks

Gail Badner added a comment - 21/Aug/08 01:53 PM
My guess is that a corrupt prepared statement gets cached and reused.

What version of Hibernate are you using?

Please attach mappings and any queries (e.g., criteria, HQL, named, native) that are involved with this exception.

Nicolas Savois added a comment - 10/Feb/09 06:30 AM
It was DBCP which was creating the bug...

the poolPreparedStatements of DBCP is bugged... we simply disabled the functionality and everything went back to normal.
we also tried another connection pool, aka OracleDataSource which also work pretty fine (the configuration is quite complexe though)

for me is was not an hibernate bug

Nicolas Savois added a comment - 10/Feb/09 06:33 AM
oups forgot :
to test that functionality, you have to open as much prepared statement as possible.

I was stressing a single functionality of my application, without any result...
when i opened the scope of the test and created as much prepared statement as I could, then the bug appeared.