Fix OPENDJ-1152: Provide the ability to debug leaked pooled connections

Matthew Swift

20.50.2013 892f21f9d9a9d78eeec9774706b39fa036a0ca9b

Fix OPENDJ-1152: Provide the ability to debug leaked pooled connections

Added some low level debugging and instrumentation to the SDK in order to allow app developers to detect resource leaks such as leaking pooled connections. To enable it start the JVM with the following options: 

-Dorg.forgerock.opendj.debug=true        --- enable debug instrumentation, such as tracking leaked pooled connections 
-Dorg.forgerock.opendj.debug.stderr=true --- direct debug messages to stderr instead of to j.u.l Logger.

 opendj-sdk/opendj3/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/util/StaticUtils.java

@@ -72,6 +72,21 @@
    public static final Logger DEBUG_LOG = Logger.getLogger("org.forgerock.opendj.ldap");

    /**
     * Indicates whether the SDK is being used in debug mode. In debug mode
     * components may enable certain instrumentation in order to help debug
     * applications.
     */
    public static final boolean DEBUG_ENABLED =
            System.getProperty("org.forgerock.opendj.debug") != null;

    private static final boolean DEBUG_TO_STDERR = System
            .getProperty("org.forgerock.opendj.debug.stderr") != null;

    static {
        logIfDebugEnabled("debugging enabled", null);
    }

    /**
     * The end-of-line character for this platform.
     */
    public static final String EOL = System.getProperty("line.separator");
@@ -2162,6 +2177,51 @@
    }

    /**
     * Returns the stack trace for the calling method, but only if SDK debugging
     * is enabled.
     *
     * @return The stack trace for the calling method, but only if SDK debugging
     *         is enabled, otherwise {@code null}..
     */
    public static StackTraceElement[] getStackTraceIfDebugEnabled() {
        if (!DEBUG_ENABLED) {
            return null;
        } else {
            final StackTraceElement[] stack = Thread.currentThread().getStackTrace();
            return Arrays.copyOfRange(stack, 2, stack.length);
        }
    }

    /**
     * Logs the provided message and stack trace if SDK debugging is enabled to
     * either stderr or the debug logger.
     *
     * @param msg
     *            The message to be logged.
     * @param stackTrace
     *            The stack trace, which may be {@code null}.
     */
    public static void logIfDebugEnabled(final String msg, final StackTraceElement[] stackTrace) {
        if (DEBUG_ENABLED) {
            final StringBuilder builder = new StringBuilder("OPENDJ SDK: ");
            builder.append(msg);
            if (stackTrace != null) {
                builder.append(System.lineSeparator());
                for (StackTraceElement e : stackTrace) {
                    builder.append("\tat ");
                    builder.append(String.valueOf(e));
                    builder.append(System.lineSeparator());
                }
            }
            if (DEBUG_TO_STDERR) {
                System.err.println(builder.toString());
            } else if (DEBUG_LOG.isLoggable(Level.SEVERE)) {
                DEBUG_LOG.severe(builder.toString());
            }
        }
    }

    /**
     * Retrieves the printable ASCII representation of the provided byte.
     *
     * @param b

 opendj-sdk/opendj3/opendj-ldap-sdk/src/main/java/org/forgerock/opendj/ldap/CachedConnectionPool.java

@@ -27,8 +27,11 @@

package org.forgerock.opendj.ldap;

import static com.forgerock.opendj.util.StaticUtils.DEBUG_ENABLED;
import static com.forgerock.opendj.util.StaticUtils.DEBUG_LOG;
import static com.forgerock.opendj.util.StaticUtils.DEFAULT_SCHEDULER;
import static com.forgerock.opendj.util.StaticUtils.getStackTraceIfDebugEnabled;
import static com.forgerock.opendj.util.StaticUtils.logIfDebugEnabled;
import static org.forgerock.opendj.ldap.CoreMessages.ERR_CONNECTION_POOL_CLOSING;
import static org.forgerock.opendj.ldap.ErrorResultException.newErrorResult;

@@ -124,7 +127,7 @@
     * the client application closes this connection. More specifically, pooled
     * connections are not actually stored in the internal queue.
     */
    private final class PooledConnection implements Connection, ConnectionEventListener {
    class PooledConnection implements Connection, ConnectionEventListener {
        private final Connection connection;
        private ErrorResultException error = null;
        private final AtomicBoolean isClosed = new AtomicBoolean(false);
@@ -132,7 +135,7 @@
        private List<ConnectionEventListener> listeners = null;
        private final Object stateLock = new Object();

        private PooledConnection(final Connection connection) {
        PooledConnection(final Connection connection) {
            this.connection = connection;
        }

@@ -582,6 +585,24 @@
        }
    }

    private final class DebugEnabledPooledConnection extends PooledConnection {
        private final StackTraceElement[] stackTrace;

        private DebugEnabledPooledConnection(final Connection connection,
                final StackTraceElement[] stackTrace) {
            super(connection);
            this.stackTrace = stackTrace;
        }

        @Override
        protected void finalize() throws Throwable {
            if (!isClosed()) {
                logIfDebugEnabled("CONNECTION POOL: connection leaked! It was allocated here: ",
                        stackTrace);
            }
        }
    }

    /**
     * A queue element is either a pending connection request future awaiting an
     * {@code Connection} or it is an unused {@code Connection} awaiting a
@@ -590,17 +611,21 @@
    private static final class QueueElement {
        private final long timestampMillis;
        private final Object value;
        private final StackTraceElement[] stack;

        QueueElement(final Connection connection, final long timestampMillis) {
            this.value = connection;
            this.timestampMillis = timestampMillis;
            this.stack = null;
        }

        QueueElement(final ResultHandler<? super Connection> handler, final long timestampMillis) {
        QueueElement(final ResultHandler<? super Connection> handler, final long timestampMillis,
                final StackTraceElement[] stack) {
            this.value =
                    new AsynchronousFutureResult<Connection, ResultHandler<? super Connection>>(
                            handler);
            this.timestampMillis = timestampMillis;
            this.stack = stack;
        }

        @Override
@@ -608,6 +633,10 @@
            return String.valueOf(value);
        }

        StackTraceElement[] getStackTrace() {
            return stack;
        }

        Connection getWaitingConnection() {
            if (value instanceof Connection) {
                return (Connection) value;
@@ -740,7 +769,9 @@
                } else if (hasWaitingConnections()) {
                    holder = queue.removeFirst();
                } else {
                    holder = new QueueElement(handler, timeSource.currentTimeMillis());
                    holder =
                            new QueueElement(handler, timeSource.currentTimeMillis(),
                                    getStackTraceIfDebugEnabled());
                    queue.add(holder);
                }
            }
@@ -749,7 +780,8 @@
                // There was a completed connection attempt.
                final Connection connection = holder.getWaitingConnection();
                if (connection.isValid()) {
                    final PooledConnection pooledConnection = new PooledConnection(connection);
                    final PooledConnection pooledConnection =
                            newPooledConnection(connection, getStackTraceIfDebugEnabled());
                    if (handler != null) {
                        handler.handleResult(pooledConnection);
                    }
@@ -854,7 +886,17 @@
                }
            }
        } else {
            holder.getWaitingFuture().handleResult(new PooledConnection(connection));
            holder.getWaitingFuture().handleResult(
                    newPooledConnection(connection, holder.getStackTrace()));
        }
    }

    private PooledConnection newPooledConnection(final Connection connection,
            final StackTraceElement[] stack) {
        if (!DEBUG_ENABLED) {
            return new PooledConnection(connection);
        } else {
            return new DebugEnabledPooledConnection(connection, stack);
        }
    }


 opendj-sdk/opendj3/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/ConnectionFactoryTestCase.java

@@ -95,7 +95,7 @@
        }

        public void handleResult(final Connection con) {
            //
            con.close();
            latch.countDown();
        }
    }

 opendj-sdk/opendj3/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/ConnectionPoolTestCase.java

@@ -264,6 +264,7 @@

        pc1.close();
        pc2.close();
        pc3.close();
        pool.close();
    }