From 976da4aa6126aefd775b7c223c71e29d1207bf10 Mon Sep 17 00:00:00 2001
From: Matthew Swift <matthew.swift@forgerock.com>
Date: Wed, 11 Dec 2013 17:17:53 +0000
Subject: [PATCH] Fix OPENDJ-1247: Client side timeouts do not cancel bind or startTLS requests properly

---
 opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPExtendedFutureResultImpl.java  |    9 -
 opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/AbstractLDAPFutureResultImpl.java  |   23 ++++
 opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPBindFutureResultImpl.java      |    9 -
 opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPConnection.java                |  133 ++++++++++++++++++++------
 opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/LDAPConnectionFactoryTestCase.java |  104 +++++++++++++++++++-
 opendj-ldap-sdk/src/main/resources/org/forgerock/opendj/ldap/core.properties               |    8 +
 6 files changed, 235 insertions(+), 51 deletions(-)

diff --git a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/AbstractLDAPFutureResultImpl.java b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/AbstractLDAPFutureResultImpl.java
index 0558a48..a7b896c 100644
--- a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/AbstractLDAPFutureResultImpl.java
+++ b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/AbstractLDAPFutureResultImpl.java
@@ -94,11 +94,34 @@
      */
     @Override
     protected final ErrorResultException handleCancelRequest(final boolean mayInterruptIfRunning) {
+        /*
+         * This will abandon the request, but will also recursively cancel this
+         * future. There is no risk of an infinite loop because the state of
+         * this future has already been changed.
+         */
         connection.abandonAsync(Requests.newAbandonRequest(requestID));
         return null;
     }
 
     @Override
+    protected final boolean isCancelable() {
+        /*
+         * No other operations can be performed while a bind or startTLS
+         * operations is active. Therefore it is not possible to cancel bind or
+         * startTLS requests, since doing so will leave the connection in a
+         * state which prevents other operations from being performed.
+         */
+        return !isBindOrStartTLS();
+    }
+
+    /**
+     * Returns {@code false} by default.
+     */
+    boolean isBindOrStartTLS() {
+        return false;
+    }
+
+    @Override
     protected void toString(final StringBuilder sb) {
         sb.append(" requestID = ");
         sb.append(requestID);
diff --git a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPBindFutureResultImpl.java b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPBindFutureResultImpl.java
index e8309ce..2080e12 100644
--- a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPBindFutureResultImpl.java
+++ b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPBindFutureResultImpl.java
@@ -22,7 +22,7 @@
  *
  *
  *      Copyright 2009-2010 Sun Microsystems, Inc.
- *      Portions copyright 2011 ForgeRock AS.
+ *      Portions copyright 2011-2013 ForgeRock AS.
  */
 
 package com.forgerock.opendj.ldap;
@@ -49,12 +49,9 @@
         this.bindClient = bindClient;
     }
 
-    /**
-     * {@inheritDoc}
-     */
     @Override
-    protected boolean isCancelable() {
-        return false;
+    boolean isBindOrStartTLS() {
+        return true;
     }
 
     @Override
diff --git a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPConnection.java b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPConnection.java
index 68c95ed..8829372 100644
--- a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPConnection.java
+++ b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPConnection.java
@@ -28,7 +28,9 @@
 package com.forgerock.opendj.ldap;
 
 import static com.forgerock.opendj.util.StaticUtils.DEBUG_LOG;
+import static org.forgerock.opendj.ldap.CoreMessages.*;
 import static org.forgerock.opendj.ldap.ErrorResultException.newErrorResult;
+import static org.forgerock.opendj.ldap.requests.Requests.newAbandonRequest;
 
 import java.io.IOException;
 import java.net.InetSocketAddress;
@@ -65,7 +67,6 @@
 import org.forgerock.opendj.ldap.requests.GenericBindRequest;
 import org.forgerock.opendj.ldap.requests.ModifyDNRequest;
 import org.forgerock.opendj.ldap.requests.ModifyRequest;
-import org.forgerock.opendj.ldap.requests.Requests;
 import org.forgerock.opendj.ldap.requests.SearchRequest;
 import org.forgerock.opendj.ldap.requests.StartTLSExtendedRequest;
 import org.forgerock.opendj.ldap.requests.UnbindRequest;
@@ -128,40 +129,64 @@
 
     @Override
     public FutureResult<Void> abandonAsync(final AbandonRequest request) {
-        final AbstractLDAPFutureResultImpl<?> pendingRequest;
-        final int messageID = nextMsgID.getAndIncrement();
+        /*
+         * Need to be careful here since both abandonAsync and Future.cancel can
+         * be called separately by the client application. Therefore
+         * future.cancel() should abandon the request, and abandonAsync should
+         * cancel the future. In addition, bind or StartTLS requests cannot be
+         * abandoned.
+         */
         try {
             synchronized (stateLock) {
                 checkConnectionIsValid();
-                checkBindOrStartTLSInProgress();
-                // Remove the future associated with the request to be abandoned.
-                pendingRequest = pendingRequests.remove(request.getRequestID());
-            }
-            if (pendingRequest == null) {
                 /*
-                 * There has never been a request with the specified message ID
-                 * or the response has already been received and handled. We can
-                 * ignore this abandon request.
+                 * If there is a bind or startTLS in progress then it must be
+                 * this request which is being abandoned. The following check
+                 * will prevent it from happening.
                  */
-
-                // Message ID will be -1 since no request was sent.
-                return new CompletedFutureResult<Void>((Void) null);
-            }
-            pendingRequest.cancel(false);
-            try {
-                final ASN1BufferWriter asn1Writer = ASN1BufferWriter.getWriter();
-                try {
-                    ldapWriter.abandonRequest(asn1Writer, messageID, request);
-                    connection.write(asn1Writer.getBuffer(), null);
-                    return new CompletedFutureResult<Void>((Void) null, messageID);
-                } finally {
-                    asn1Writer.recycle();
-                }
-            } catch (final IOException e) {
-                throw adaptRequestIOException(e);
+                checkBindOrStartTLSInProgress();
             }
         } catch (final ErrorResultException e) {
-            return new CompletedFutureResult<Void>(e, messageID);
+            return new CompletedFutureResult<Void>(e);
+        }
+
+        // Remove the future associated with the request to be abandoned.
+        final AbstractLDAPFutureResultImpl<?> pendingRequest =
+                pendingRequests.remove(request.getRequestID());
+        if (pendingRequest == null) {
+            /*
+             * There has never been a request with the specified message ID or
+             * the response has already been received and handled. We can ignore
+             * this abandon request.
+             */
+            return new CompletedFutureResult<Void>((Void) null);
+        }
+
+        /*
+         * This will cancel the future, but will also recursively invoke this
+         * method. Since the pending request has been removed, there is no risk
+         * of an infinite loop.
+         */
+        pendingRequest.cancel(false);
+
+        /*
+         * FIXME: there's a potential race condition here if a bind or startTLS
+         * is initiated just after we removed the pending request.
+         */
+        return sendAbandonRequest(request);
+    }
+
+    private FutureResult<Void> sendAbandonRequest(final AbandonRequest request) {
+        final ASN1BufferWriter asn1Writer = ASN1BufferWriter.getWriter();
+        try {
+            final int messageID = nextMsgID.getAndIncrement();
+            ldapWriter.abandonRequest(asn1Writer, messageID, request);
+            connection.write(asn1Writer.getBuffer(), null);
+            return new CompletedFutureResult<Void>((Void) null, messageID);
+        } catch (final IOException e) {
+            return new CompletedFutureResult<Void>(adaptRequestIOException(e));
+        } finally {
+            asn1Writer.recycle();
         }
     }
 
@@ -557,10 +582,54 @@
                 if (future != null && future.checkForTimeout()) {
                     final long diff = (future.getTimestamp() + timeout) - currentTime;
                     if (diff <= 0 && pendingRequests.remove(requestID) != null) {
-                        DEBUG_LOG.fine("Cancelling expired future result: " + future);
-                        final Result result = Responses.newResult(ResultCode.CLIENT_SIDE_TIMEOUT);
-                        future.adaptErrorResult(result);
-                        abandonAsync(Requests.newAbandonRequest(future.getRequestID()));
+                        if (future.isBindOrStartTLS()) {
+                            /*
+                             * No other operations can be performed while a bind
+                             * or StartTLS request is active, so we cannot time
+                             * out the request. We therefore have a choice:
+                             * either ignore timeouts for these operations, or
+                             * enforce them but doing so requires invalidating
+                             * the connection. We'll do the latter, since
+                             * ignoring timeouts could cause the application to
+                             * hang.
+                             */
+                            DEBUG_LOG.fine("Failing bind or StartTLS request due to timeout "
+                                    + "(connection will be invalidated): " + future);
+                            final Result result =
+                                    Responses.newResult(ResultCode.CLIENT_SIDE_TIMEOUT)
+                                            .setDiagnosticMessage(
+                                                    LDAP_CONNECTION_BIND_OR_START_TLS_REQUEST_TIMEOUT
+                                                            .get(timeout).toString());
+                            future.adaptErrorResult(result);
+
+                            // Fail the connection.
+                            final Result errorResult =
+                                    Responses.newResult(ResultCode.CLIENT_SIDE_TIMEOUT)
+                                            .setDiagnosticMessage(
+                                                    LDAP_CONNECTION_BIND_OR_START_TLS_CONNECTION_TIMEOUT
+                                                            .get(timeout).toString());
+                            connectionErrorOccurred(errorResult);
+                        } else {
+                            DEBUG_LOG.fine("Failing request due to timeout: " + future);
+                            final Result result =
+                                    Responses.newResult(ResultCode.CLIENT_SIDE_TIMEOUT)
+                                            .setDiagnosticMessage(
+                                                    LDAP_CONNECTION_REQUEST_TIMEOUT.get(timeout)
+                                                            .toString());
+                            future.adaptErrorResult(result);
+
+                            /*
+                             * FIXME: there's a potential race condition here if
+                             * a bind or startTLS is initiated just after we
+                             * check the boolean. It seems potentially even more
+                             * dangerous to send the abandon request while
+                             * holding the state lock, since a blocking write
+                             * could hang the application.
+                             */
+                            if (!bindOrStartTLSInProgress.get()) {
+                                sendAbandonRequest(newAbandonRequest(requestID));
+                            }
+                        }
                     } else {
                         delay = Math.min(delay, diff);
                     }
diff --git a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPExtendedFutureResultImpl.java b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPExtendedFutureResultImpl.java
index 7dfe521..8d75302 100644
--- a/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPExtendedFutureResultImpl.java
+++ b/opendj-ldap-sdk/src/main/java/com/forgerock/opendj/ldap/LDAPExtendedFutureResultImpl.java
@@ -22,7 +22,7 @@
  *
  *
  *      Copyright 2009-2010 Sun Microsystems, Inc.
- *      Portions copyright 2011 ForgeRock AS.
+ *      Portions copyright 2011-2013 ForgeRock AS.
  */
 
 package com.forgerock.opendj.ldap;
@@ -66,12 +66,9 @@
         return sb.toString();
     }
 
-    /**
-     * {@inheritDoc}
-     */
     @Override
-    protected boolean isCancelable() {
-        return !request.getOID().equals(StartTLSExtendedRequest.OID);
+    boolean isBindOrStartTLS() {
+        return request.getOID().equals(StartTLSExtendedRequest.OID);
     }
 
     R decodeResult(final ExtendedResult result, final DecodeOptions options) throws DecodeException {
diff --git a/opendj-ldap-sdk/src/main/resources/org/forgerock/opendj/ldap/core.properties b/opendj-ldap-sdk/src/main/resources/org/forgerock/opendj/ldap/core.properties
index 1057f00..16fae6d 100755
--- a/opendj-ldap-sdk/src/main/resources/org/forgerock/opendj/ldap/core.properties
+++ b/opendj-ldap-sdk/src/main/resources/org/forgerock/opendj/ldap/core.properties
@@ -1421,4 +1421,12 @@
 HBCF_CONNECTION_CLOSED_BY_CLIENT=Connection closed by client
 HBCF_HEARTBEAT_FAILED=Heartbeat failed
 HBCF_HEARTBEAT_TIMEOUT=Heartbeat timed out after %d ms
+LDAP_CONNECTION_REQUEST_TIMEOUT=The request has failed because no response \
+ was received from the server within the %d ms timeout
+LDAP_CONNECTION_BIND_OR_START_TLS_REQUEST_TIMEOUT=The bind or StartTLS request \
+ has failed because no response was received from the server within the %d ms \
+ timeout. The LDAP connection is now in an invalid state and can no longer be used
+LDAP_CONNECTION_BIND_OR_START_TLS_CONNECTION_TIMEOUT=The LDAP connection has \
+ failed because no bind or StartTLS response was received from the server \
+ within the %d ms timeout
 
diff --git a/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/LDAPConnectionFactoryTestCase.java b/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/LDAPConnectionFactoryTestCase.java
index 26d8d6d..ed70fff 100644
--- a/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/LDAPConnectionFactoryTestCase.java
+++ b/opendj-ldap-sdk/src/test/java/org/forgerock/opendj/ldap/LDAPConnectionFactoryTestCase.java
@@ -27,6 +27,7 @@
 
 import static com.forgerock.opendj.util.StaticUtils.closeSilently;
 import static org.fest.assertions.Assertions.assertThat;
+import static org.fest.assertions.Fail.fail;
 import static org.forgerock.opendj.ldap.TestCaseUtils.findFreeSocketAddress;
 import static org.forgerock.opendj.ldap.requests.Requests.newSimpleBindRequest;
 import static org.mockito.Mockito.*;
@@ -42,6 +43,7 @@
 import org.forgerock.opendj.ldap.requests.UnbindRequest;
 import org.forgerock.opendj.ldap.responses.BindResult;
 import org.forgerock.opendj.ldap.responses.SearchResultEntry;
+import org.mockito.ArgumentCaptor;
 import org.mockito.invocation.InvocationOnMock;
 import org.mockito.stubbing.Answer;
 import org.mockito.stubbing.Stubber;
@@ -61,10 +63,8 @@
      * and no other operations can be performed. Therefore, a timeout should
      * cause the connection to become invalid and an appropriate connection
      * event sent. In addition, no abandon request should be sent.
-     * <p>
-     * This test is failing because the connection remains valid.
      */
-    @Test(enabled = false)
+    @Test
     public void testClientSideTimeoutForBindRequest() throws Exception {
         final AtomicReference<LDAPClientContext> context = new AtomicReference<LDAPClientContext>();
         final Semaphore latch = new Semaphore(0);
@@ -106,12 +106,17 @@
             // Wait for the request to timeout.
             try {
                 future.get(TEST_TIMEOUT, TimeUnit.SECONDS);
+                fail("The bind request succeeded unexpectedly");
             } catch (TimeoutResultException e) {
                 assertThat(e.getResult().getResultCode()).isEqualTo(ResultCode.CLIENT_SIDE_TIMEOUT);
                 verify(handler).handleErrorResult(same(e));
 
                 // The connection should no longer be valid.
-                verify(listener).handleConnectionError(eq(false), same(e));
+                ArgumentCaptor<ErrorResultException> capturedError =
+                        ArgumentCaptor.forClass(ErrorResultException.class);
+                verify(listener).handleConnectionError(eq(false), capturedError.capture());
+                assertThat(capturedError.getValue().getResult().getResultCode()).isEqualTo(
+                        ResultCode.CLIENT_SIDE_TIMEOUT);
                 assertThat(connection.isValid()).isFalse();
                 connection.close();
 
@@ -137,14 +142,98 @@
     }
 
     /**
+     * Unit test for OPENDJ-1247: as per previous test, except this time verify
+     * that the connection failure removes the connection from a connection
+     * pool.
+     */
+    @Test
+    public void testClientSideTimeoutForBindRequestInConnectionPool() throws Exception {
+        final AtomicReference<LDAPClientContext> context = new AtomicReference<LDAPClientContext>();
+        final Semaphore latch = new Semaphore(0);
+
+        // The server connection should receive a bind, but no abandon request.
+        final ServerConnection<Integer> serverConnection = mock(ServerConnection.class);
+        release(latch).when(serverConnection).handleBind(any(Integer.class), anyInt(),
+                any(BindRequest.class), any(IntermediateResponseHandler.class),
+                any(ResultHandler.class));
+        release(latch).when(serverConnection).handleConnectionClosed(any(Integer.class),
+                any(UnbindRequest.class));
+
+        final LDAPListener server = createServer(latch, context, serverConnection);
+        final ConnectionFactory factory =
+                Connections.newFixedConnectionPool(
+                        new LDAPConnectionFactory(server.getSocketAddress(), new LDAPOptions()
+                                .setTimeout(1, TimeUnit.MILLISECONDS)), 10);
+        Connection connection = null;
+        try {
+            // Get pooled connection to the server.
+            connection = factory.getConnection();
+
+            // Wait for the server to accept the connection.
+            assertThat(latch.tryAcquire(TEST_TIMEOUT, TimeUnit.SECONDS)).isTrue();
+
+            /*
+             * Sanity check: close the connection and reopen. There should be no
+             * interactions with the server due to the pool.
+             */
+            connection.close();
+            connection = factory.getConnection();
+            verifyNoMoreInteractions(serverConnection);
+
+            // Now bind with timeout.
+            final ResultHandler<BindResult> handler = mock(ResultHandler.class);
+            final FutureResult<BindResult> future =
+                    connection.bindAsync(newSimpleBindRequest(), null, handler);
+
+            // Wait for the server to receive the bind request.
+            assertThat(latch.tryAcquire(TEST_TIMEOUT, TimeUnit.SECONDS)).isTrue();
+
+            // Wait for the request to timeout.
+            try {
+                future.get(TEST_TIMEOUT, TimeUnit.SECONDS);
+                fail("The bind request succeeded unexpectedly");
+            } catch (TimeoutResultException e) {
+                assertThat(e.getResult().getResultCode()).isEqualTo(ResultCode.CLIENT_SIDE_TIMEOUT);
+                verify(handler).handleErrorResult(same(e));
+
+                // The connection should no longer be valid.
+                assertThat(connection.isValid()).isFalse();
+                connection.close();
+
+                // Wait for the server to receive the close request.
+                assertThat(latch.tryAcquire(TEST_TIMEOUT, TimeUnit.SECONDS)).isTrue();
+
+                /*
+                 * Check that the only interactions were the bind and the close
+                 * and specifically there was no abandon request.
+                 */
+                verify(serverConnection).handleBind(any(Integer.class), eq(3),
+                        any(BindRequest.class), any(IntermediateResponseHandler.class),
+                        any(ResultHandler.class));
+                verify(serverConnection).handleConnectionClosed(any(Integer.class),
+                        any(UnbindRequest.class));
+                verifyNoMoreInteractions(serverConnection);
+
+                // Now get another connection. This time we should reconnect to the server.
+                connection = factory.getConnection();
+
+                // Wait for the server to accept the connection.
+                assertThat(latch.tryAcquire(TEST_TIMEOUT, TimeUnit.SECONDS)).isTrue();
+            }
+        } finally {
+            closeSilently(connection);
+            factory.close();
+            server.close();
+        }
+    }
+
+    /**
      * Unit test for OPENDJ-1247: a locally timed out request which is not a
      * bind or startTLS should result in a client side timeout error, but the
      * connection should remain valid. In addition, no abandon request should be
      * sent.
-     * <p>
-     * This test is failing because no abandon request is received.
      */
-    @Test(enabled = false)
+    @Test
     public void testClientSideTimeoutForSearchRequest() throws Exception {
         final AtomicReference<LDAPClientContext> context = new AtomicReference<LDAPClientContext>();
         final Semaphore latch = new Semaphore(0);
@@ -186,6 +275,7 @@
             // Wait for the request to timeout.
             try {
                 future.get(TEST_TIMEOUT, TimeUnit.SECONDS);
+                fail("The search request succeeded unexpectedly");
             } catch (TimeoutResultException e) {
                 assertThat(e.getResult().getResultCode()).isEqualTo(ResultCode.CLIENT_SIDE_TIMEOUT);
                 verify(handler).handleErrorResult(same(e));

--
Gitblit v1.10.0