JdbcConnectionPool generates 'Connection not closed' error logs on recycled connection

[GoogleCodeExporter]

Hi,

The gargage collector closes physical connections even if they are in the
JdbcConnectionPool recycle Stack, 
resulting by the following unexpected log line (and probably some other
side effects..):
07-06 03:12:16 jdbc[2]: Connection not closed

To reproduce (version .115):
============================
    public static void main(String[] args) {
    JdbcConnectionPool pool =
JdbcConnectionPool.create("jdbc:h2:file:/tmp/test;TRACE_LEVEL_FILE=3","test","te
st");
    pool.setMaxConnections(10);
    try {
        Connection conn = pool.getConnection();
        conn.close();
        conn = null;  // Ensure 
        System.gc();
        System.runFinalization();
    } catch (SQLException ex) {
        ex.printStackTrace();
    }
    // Sleep to let the garbage collector doing its job.
    // The 'Connection not closed' log line will occurs during that sleep and
before pool.dispose()
    try {
        Thread.sleep(15000);
    } catch (InterruptedException ex) {
        ex.printStackTrace();
    }
    try {
        pool.dispose();
    } catch (SQLException ex) {
        ex.printStackTrace();
    }
    }

The error log line will occur during the sleep and before pool.dispose() call.

Cause:
======
After some investigations, i think that the cause start from the following
call in JdbcXAConnection:
handleConn = new PooledJdbcConnection(physicalConn);

A new PooledJdbcConnection is created as 'handleConn'.
When close() is called by the user application, the
JdbcXAConnection#closedHandle() is internally 
called and the JdbcXAConnection 'handleConn' field is set to null.
Therefore, the PooledJdbcConnection will be garbage collected.
However, since that PooledJdbcConnection inherit the JdbcConnection, the
finalize() of JdbcConnection
is called, the physical connection is closed and the 'Connection not
closed' error is logged.

Workarround ideas:
==================
-Override the finalize() method in the inner class PooledJdbcConnection
extends JdbcConnection {
 with an empty statement.

-Or maybe set isInternal to true in the public
JdbcConnection(JdbcConnection clone) constructor.

I started to read the source code of H2 today only, i cannot confirm the
validity of these workarround yet.

Additional INFOS:
=================
H2 Version .115
SUN JDK: jdk1.6.0_14
(The version of the JDK may affect the garbage collector processing.)
Plateform: linux

Regards,
Cédric.

Original issue reported on code.google.com by ppced...@gmail.com on 6 Jul 2009 at 1:59

[GoogleCodeExporter]

Well, it seems that the side effect is only that 'Connection not closed' log 
line,
this do not close the physical connection since close() is overriden by the
PooledJdbcConnection inner class.

So, i simply suggest to override the finalizer of the inner class
JdbcXAConnection#PooledJdbcConnection with
such kind of statement:

protected void finalize() {
    if (!isClosed) {
        trace.error("Pooled connection not closed");
        try {
            close();
        } catch (SQLException e) {
            trace.debug("finalize", e);
        }
    }
}

With the 'trace' field modifier changed from 'private' to 'protected' in
JdbcConnection class.

That workarround seems to works for me..

Original comment by ppced...@gmail.com on 6 Jul 2009 at 2:38

[GoogleCodeExporter]

Hi,

There is definetly something wrong with the finalizer in
JdbcXAConnection$PooledJdbcConnection. My test case is:

DeleteDbFiles.execute("data", null, false);
JdbcConnectionPool cp = JdbcConnectionPool.create(
        "jdbc:h2:data/tr;TRACE_LEVEL_SYSTEM_OUT=3", "sa", "sa");
for (int i = 0; i < 10; i++) {
    Connection c = cp.getConnection();
    System.out.println("conn: " + c + " " + c.getClass().getName());
    System.gc();
    // c.close();
    Thread.sleep(1000);
}
System.out.println("dispose------");
cp.dispose();
for (int i = 0; i < 10; i++) {
    System.gc();
    Thread.sleep(100);
}

I think what should happen is that the pooled connection is closed in the 
finalizer.
First I tried to return the connection to the pool, but actually that doesn't 
work
because the finalizers of both the pooled connection and the physical 
connection are
called in the same garbage collection cycle. If this happens, the connection in 
the
pool would be closed (which is really bad).

My fix is a bit different, I have now committed it to the trunk.

Regards,
Thomas

Original comment by thomas.t...@gmail.com on 10 Jul 2009 at 4:16

• Changed state: Accepted

[GoogleCodeExporter]

Original comment by thomas.t...@gmail.com on 10 Jul 2009 at 4:16

[GoogleCodeExporter]

This bug is fixed with the latest release (1.1.116).
If there is still a problem, please open a new issue
or add a comment to this issue.

Original comment by thomas.t...@gmail.com on 18 Jul 2009 at 9:55

• Changed state: Fixed