Learn how easy it is to sync an existing GitHub or Google Code repo to a SourceForge project! See Demo

Close

#32 cached statements closing connections prematurely

v1.0 (example)
open
nobody
5
2014-08-14
2006-04-11
zachm
No

Hi,

This bug is similar to:

http://sourceforge.net/tracker/index.php?func=detail&aid=1164218&group_id=25357&atid=383690

I'm using c3p0 version 0.9.1.pre5a with Hibernate
3.1.2. I'm getting hard-to-reproduce errors in my
application:

2006-04-10 18:16:18,686 ERROR [http-8080-Processor23]
util.JDBCExceptionReporter
(JDBCExceptionReporter.java:72) - You can't operate
on a closed connection!!!
2006-04-10 18:16:18,686 ERROR [http-8080-Processor23]
package_version.GetAllPackageVersionsByPackageName
(PublicReadOnlyMethodAdapter.java:21) - An error
occurred:
org.hibernate.exception.GenericJDBCException: could not
load an entity: [org.sample.event.EventBean#0]
at
org.hibernate.exception.ErrorCodeConverter.handledNonSpecificException(ErrorCodeConverter.java:92)
at
org.hibernate.exception.ErrorCodeConverter.convert(ErrorCodeConverter.java:80)
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at
org.hibernate.loader.Loader.loadEntity(Loader.java:1359)
at
org.hibernate.loader.entity.EntityLoader.load(EntityLoader.java:116)
at
org.hibernate.loader.entity.EntityLoader.load(EntityLoader.java:101)
at
org.hibernate.persister.entity.BasicEntityPersister.load(BasicEntityPersister.java:2471)
at
org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:351)
at
org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:332)
at
org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:113)
at
org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:167)
at
org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:79)
at
org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:655)
at
org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:261)
at
org.hibernate.type.EntityType.resolve(EntityType.java:286)
at
org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:105)
at
org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:530)
at
org.hibernate.loader.Loader.doQuery(Loader.java:436)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at
org.hibernate.loader.Loader.doList(Loader.java:1593)
at
org.hibernate.loader.Loader.list(Loader.java:1577)
at
org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:395)
at
org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:271)
at
org.hibernate.impl.SessionImpl.list(SessionImpl.java:844)
at
org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)

[snipped irrelevent lines]

Caused by: java.sql.SQLException: You can't operate on
a closed connection!!!
at
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:68)
at
com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.close(NewProxyPreparedStatement.java:1682)
at
org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:417)
at
org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:197)
at
org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:213)
at
org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:143)
at
org.hibernate.loader.Loader.doQuery(Loader.java:433)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at
org.hibernate.loader.Loader.loadEntity(Loader.java:1345)
... 60 more
Caused by: java.lang.NullPointerException

This occurs every 20 or so service calls. I can
reproduce it on a local deployment of the service just
by calling the method over and over, but the behavior
is inherently random. Disabling statement caching by
setting hibernate.c3p0.max_statements=0 makes this
problem disappear.

I've only seen this problem occur when the entity being
referenced doesn't exist -- in the example above, there
is no EventBean with ID 0 in the database.

Is this a bug in hibernate, or do you have some advice
for me?

Discussion

  • Steve Waldman
    Steve Waldman
    2006-09-07

    Logged In: YES
    user_id=175530

    [i'm sorry this has gone unanswered or addressed for so
    long. i'm puzzled by the stack trace, line 1682 of
    c3p0-0.9.1-pre5a falls in addBatch (which should complain
    about being called if its parent Connection has been
    called), not in close() which should not. it's interesting
    that statement caching seems to be involved; nothing in your
    stack traces seems to hint that. if you still see this
    problem when you turn statement caching on, can you try it
    with the most recent version, and if the problem persists,
    send along more information (including the irrelevant parts
    of stack traces you omitted, so i can try to get some better
    sense of what's going on, and c3p0's version banner and
    configuration dump.) Thanks, and sorry again.]

     
  • Hugo
    Hugo
    2006-10-06

    Logged In: YES
    user_id=1613706

    I do have a similar behavior with the C3P0-0_9_1-pre9
    version (and hibernate 3.1 too):

    It seems to occur mainly under heavy load (8 connections
    creation in few seconds)

    connection creation timestamp:

    [- CONNECTION CREATION TIMESTAMP -]

    INFO [RMI TCP Connection(176)-10.0.0.36] TISRepository () -
    2006-10-06 13:57:31,843 - Create new session for thread RMI
    TCP Connection(176)-10.0.0.36

    INFO [RMI TCP Connection(176)-10.0.0.36] TISRepository () -
    2006-10-06 13:57:42,109 - Create new TEMPORARY session for
    thread RMI TCP Connection(176)-10.0.0.36

    INFO [RMI TCP Connection(180)-10.0.0.36] TISRepository () -
    2006-10-06 13:58:12,515 - Create new session for thread RMI
    TCP Connection(180)-10.0.0.36

    INFO [RMI TCP Connection(184)-10.0.0.36] TISRepository () -
    2006-10-06 13:58:53,062 - Create new session for thread RMI
    TCP Connection(184)-10.0.0.36

    INFO [RMI TCP Connection(199)-10.0.0.36] TISRepository () -
    2006-10-06 14:01:18,703 - Create new session for thread RMI
    TCP Connection(199)-10.0.0.36

    INFO [RMI TCP Connection(199)-10.0.0.36] TISRepository () -
    2006-10-06 14:01:30,281 - Create new TEMPORARY session for
    thread RMI TCP Connection(199)-10.0.0.36

    INFO [RMI TCP Connection(205)-10.0.0.36] TISRepository () -
    2006-10-06 14:02:22,921 - Create new session for thread RMI
    TCP Connection(205)-10.0.0.36

    INFO [RMI TCP Connection(209)-10.0.0.36] TISRepository () -
    2006-10-06 14:02:35,609 - Create new session for thread RMI
    TCP Connection(209)-10.0.0.36

    [- STACK TRACE -]

    org.hibernate.exception.GenericJDBCException: could not
    execute query

    at
    org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)

    at
    org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)

    at
    org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)

    at
    org.hibernate.loader.Loader.doList(Loader.java:2148)

    at
    org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2029)

    at
    org.hibernate.loader.Loader.list(Loader.java:2024)

    at
    org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)

    at
    org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:308)

    at
    org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:153)

    at
    org.hibernate.impl.SessionImpl.list(SessionImpl.java:1106)

    at
    org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)

    at
    com.temis.idm.tis.document.data.impl.AnalysisDAO.getAnnotationOccurrences(AnalysisDAO.java:1305)

    at
    sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at
    sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

    at
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

    at java.lang.reflect.Method.invoke(Method.java:324)

    at
    sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:261)

    at
    sun.rmi.transport.Transport$1.run(Transport.java:148)

    at
    java.security.AccessController.doPrivileged(Native Method)

    at
    sun.rmi.transport.Transport.serviceCall(Transport.java:144)

    at
    sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)

    at
    sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)

    at java.lang.Thread.run(Thread.java:534)

    Caused by: java.sql.SQLException: You can't operate on a
    closed Statement!!!

    at
    com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)

    at
    com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)

    at
    com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:85)

    at
    org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:139)

    at
    org.hibernate.loader.Loader.getResultSet(Loader.java:1669)

    at
    org.hibernate.loader.Loader.doQuery(Loader.java:662)

    at
    org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)

    at
    org.hibernate.loader.Loader.doList(Loader.java:2145)

    ... 19 more

    Caused by: java.lang.NullPointerException

    at
    com.mchange.v2.c3p0.impl.NewProxyResultSet.attach(NewProxyResultSet.java:3690)

    at
    com.mchange.v2.c3p0.impl.NewProxyResultSet.<init>(NewProxyResultSet.java:3702)

    at
    com.mchange.v2.c3p0.impl.NewProxyResultSet.<init>(NewProxyResultSet.java:3714)

    at
    com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:79)

    ... 24 more

    Hope this help,

     
  • Steve Waldman
    Steve Waldman
    2006-10-06

    Logged In: YES
    user_id=175530

    Hugo,

    Can you check whether the behavior you're observing under
    c3p0-0.9.1-pre9 only occurs with statement caching enabled?
    The exception you are seeing is generated by the proxy
    statement, that wraps the cached statement, so it's not as
    one might guess a matter of the statement cache prematurely
    closing a Statement. Instead it looks as though the (proxy)
    Connection was closed concurrently with a call to
    executeQuery. The query succeeds, but the attempt to make a
    result set fails, as the result set tries to associate
    itself with a Connection now null. But close()ing the
    Connection before a query executed on a statement completes
    would be a pretty bad hibernate bug. I doubt it would only
    show up with c3p0. It's interesting that you observe this
    primarily after a burst of Connection acquisitions. Perhaps
    this occurs after c3p0 has decided an error indicates that
    all pooled Connections must be replaced? c3p0 should not
    abruptly close checked-out Connections, even in this case
    though. (I should log a message at WARNING when c3p0
    refreshes the pool due to an error that it takes to mean
    pool corruption. Right now, neither you or I would ever know.)

    In both reports, there is no obvious relationship between
    what's visible in the stack traces and the statement cache.
    So, I'd be very curious to know whether the behavior goes
    away with maxStatements / maxStatementsPerConnection both
    set to 0.

    Is this easy to reproduce? If I send you a modified version
    of the library with some extra debugging gunk to test some
    guesses, would you be able to try it, and likely to observe
    the problem?

    Thanks for the report, and any more information you can offer!

     
  • Hugo
    Hugo
    2006-10-06

    Logged In: YES
    user_id=1613706

    It occurs with c3p0.max_statements=0. I didn't try with
    maxStatementsPerConnection=0 yet, but will try next.

    It's not so easy to reproduce since it occurs randomly, but
    still quite often (once a day I will say). So feel free to
    send me a modified version, so we could get more informations.

     
  • Hugo
    Hugo
    2006-10-06

    Logged In: YES
    user_id=1613706

    By the way what is the correct spelling of the parameters ?
    (I'm using hibernate)

    c3p0.maxStatements
    c3p0.max_Statements
    hibernate.c3p0.maxStatements
    hibernate.c3p0.max_Statements ?

    and the same question for maxStatementsPerConnection.

    Maybe it is just a bad spelling problem...

     
  • Steve Waldman
    Steve Waldman
    2006-10-06

    Logged In: YES
    user_id=175530

    Hugo,

    The c3p0 parameters are c3p0.maxStatements and
    c3p0.maxStatementsPerConnection. But the way hibernate wraps
    c3p0 (I've proposed this be changed in a nondisruptive way
    several times, but so far it hasn't happened), several
    parameters must be set in hibernate's config (rather than a
    c3p0.properties file), and these parameters have hibernate
    specific names. So, for hibernate users, it's
    hibernate.c3p0.max_statements. maxStatementsPerConnection is
    not hibernate-managed, so to set that, you must defined a
    c3p0.properties file (or c3p0-config.xml), and set the
    property c3p0.maxStatementsPerConnection. See the c3p0's
    docs for the meaning of all parameters, and information on
    which parameters must be set hibernate's way, and which (all
    the rest) must be set c3p0's way in a hibernate app.

    (Sorry for the confusion. I really do hope this annoyingness
    gets resolved, but it's not something I can do unilaterally.)

    smiles,
    Steve

     
  • Hugo
    Hugo
    2006-10-06

    Logged In: YES
    user_id=1613706

    Ok. It's seems I messed up a little bit with my
    configuration files.

    I cleaned that, and FYI now I use the following configuration:

    [hibernate.cfg.xml]
    <property name="hibernate.c3p0.min_size">1</property>
    <property name="hibernate.c3p0.max_size">100</property>
    <property name="hibernate.c3p0.timeout">1200</property>
    <property name="hibernate.c3p0.idle_test_period">600</property>
    <property name="hibernate.c3p0.max_statements">0</property>

    [c3p0.properties]
    c3p0.maxStatementsPerConnection=0
    c3p0.breakAfterAcquireFailure=true
    c3p0.acquireRetryAttempts=3
    c3p0.acquireIncrement=2
    c3p0.automaticTestTable=C3P0TestTable

    Maybe the error will disapear with this config...

     
  • Logged In: NO

    Just to let you know that I still have the problem with the
    parameters set this way.

    For the moment I will desactivate the connection pool.