[#1180] Report the fail-over failure of the Grizzly proxy listener tests in...

Valery Kharseko

2 days ago a4a5cd8e4c89ba459c1105f4b25a499895a3a571

[#1180] Report the fail-over failure of the Grizzly proxy listener tests instead of timing out (#1181)

Fixes #1180

### Problem

`GrizzlyLDAPListenerTestCase#testLDAPListenerProxyDuringHandleAccept`
timed out on `windows-latest` / JDK 26 with a bare `TimeoutException` at
the first wait (line 605).

The overridden `handleAccept` connects to an offline port and then to
the online listener, and resolves the proxy's `context` only after both
succeed. It runs synchronously on a selector thread of the server
transport. Any exception before the last line therefore left that
`context` unresolved. The causes could be: the offline connection
unexpectedly succeeding, a `TimeoutResultException` (which is not a
`ConnectionException`), a failed online connection, or an unchecked
exception such as a failed loopback bind in `findFreeSocketAddress()`.
In each case the listener only closed the client connection, and the
test waited out its 10 seconds without a cause. The class runs with
logging at `SEVERE`, so the job log shows nothing either. Every way the
fail-over can fail looks the same as the CI failure, so the run cannot
tell us which one happened.

`testLDAPListenerProxyDuringHandleBind` had the same blind spot in a
different form. It failed the bind with a plain `Result`, which the
listener cannot encode as a bind response (`ClassCastException:
ResultImpl cannot be cast to BindResult` inside Grizzly). The connection
was closed and the client saw only `Server Connection Closed`, or the
test hung until its `timeOut`.

### Fix (test only)

- The overridden `handleAccept` resolves the proxy's `context` with the
failure before rethrowing it, unchecked exceptions included, so the
assert fails at once with the actual cause.
- The first wait is 30 s instead of 10 s. `handleAccept` makes two
nested connections before it resolves the context, and each may take up
to the default connect timeout (10 s). A shorter wait would again expire
before a failed attempt can report itself. Because a failure is now
reported as soon as it happens, the longer window does not hide
anything.
- The bind variant fails the bind with a `BindResult`, for unchecked
exceptions too. Only the diagnostic message of that result reaches the
client, never its cause, so the message carries the nested cause.
- Both tests share one `failOverToOnlineServer` helper. It closes the
offline and online connection factories (previously leaked). It connects
to the numeric address of the offline port: the address of the reserved
socket keeps the host name `localhost`, so neither `getHostName()` nor
`getHostString()` gives a numeric host.
- The listener addresses (the online server and both proxies) have no
host name, so `getHostName()` reverse-resolved them, for the online
server inside `handleAccept`, outside the connect timeout. They are now
used through `getHostString()`.
- The client connection factories are closed in `finally`. In
`...DuringHandleAccept`, `connection.close()` moved into `finally`, the
`isClosed` wait is bounded, and a `@Test(timeOut = 60000)` was added.
The `timeOut` of `...DuringHandleBind` goes from 10 s to 60 s, for the
same reason as the longer wait.

The root cause on Windows is still unknown: it cannot be reproduced
locally. This change makes the next occurrence name it. I also tried
reserving the offline port with a socket that is bound but not
listening, to rule out the port being reused. On macOS such a port does
not refuse connections: the connect times out instead. So the offline
port is still picked with `findFreeSocketAddress()`.

### Verification

Each mutant was run against both tests, before (BASE of the PR) and
after:

| Mutant | Before | After |
|---|---|---|
| offline address = the listening online one | accept: bare
`TimeoutException` after 11.2 s; bind: `Server Connection Closed`,
`ClassCastException` in the log | both fail in about 1 s with
`Connection to offline server succeeded unexpectedly` |
| online port = a free port (connect refused) | — | accept fails in 1 s,
with `Connection refused` in the cause chain; bind fails in 0.4 s with
`Unexpected exception when connecting to online server:
...ConnectionException: Connect Error: Connection refused` |
| `RuntimeException` at the start of the helper | — | accept fails in 1
s with `mutant: loopback bind failed`; bind fails in 0.5 s with
`java.lang.RuntimeException: mutant: loopback bind failed` |

Against the first commit of this PR, the last two mutants gave: a bind
message without the cause (`Unexpected exception when connecting to
online server`); and for the `RuntimeException`, a bare
`TimeoutException` after 31 s in the accept test and `Server Connection
Closed` in the bind test.

Without a mutant: all of `opendj-grizzly` passes, 1040 tests in 9
classes with 0 failures (`mvn verify`, checkstyle included).

 opendj-grizzly/src/test/java/org/forgerock/opendj/grizzly/GrizzlyLDAPListenerTestCase.java

@@ -204,6 +204,39 @@
        return socket;
    }

    /**
     * Fails over the way a proxy does: connects to a free port, which must refuse the connection,
     * then to the online server.
     */
    private static void failOverToOnlineServer(final InetSocketAddress onlineAddress) throws LdapException {
        // The numeric host avoids a forward lookup of "localhost".
        final InetSocketAddress offlineAddress = findFreeSocketAddress();
        final LDAPConnectionFactory offlineFactory =
                new LDAPConnectionFactory(offlineAddress.getAddress().getHostAddress(), offlineAddress.getPort());
        try {
            offlineFactory.getConnection().close();
        } catch (final ConnectionException expected) {
            // This is expected - so go to online server.
            final LDAPConnectionFactory onlineFactory =
                    new LDAPConnectionFactory(onlineAddress.getHostString(), onlineAddress.getPort());
            try {
                onlineFactory.getConnection().close();
                return;
            } catch (final Exception e) {
                throw newLdapException(ResultCode.OTHER,
                        "Unexpected exception when connecting to online server", e);
            } finally {
                onlineFactory.close();
            }
        } catch (final Exception e) {
            throw newLdapException(ResultCode.OTHER,
                    "Unexpected exception when connecting to offline server", e);
        } finally {
            offlineFactory.close();
        }
        throw newLdapException(ResultCode.OTHER, "Connection to offline server succeeded unexpectedly");
    }

    /** Disables logging before the tests. */
    @BeforeClass
    public void disableLogging() {
@@ -534,7 +567,7 @@
     * @throws Exception
     *             If an unexpected exception occurred.
     */
    @Test
    @Test(timeOut = 60000)
    public void testLDAPListenerProxyDuringHandleAccept() throws Exception {
        final MockServerConnection onlineServerConnection = new MockServerConnection();
        final MockServerConnectionFactory onlineServerConnectionFactory =
@@ -552,39 +585,19 @@
                        @Override
                        public ServerConnection<Integer> handleAccept(
                                final LDAPClientContext clientContext) throws LdapException {
                            // First attempt offline server.
                            InetSocketAddress offlineAddress = findFreeSocketAddress();
                            LDAPConnectionFactory lcf =
                                    new LDAPConnectionFactory(offlineAddress.getHostName(),
                                            offlineAddress.getPort());
                            try {
                                // This is expected to fail.
                                lcf.getConnection().close();
                                throw newLdapException(ResultCode.OTHER,
                                        "Connection to offline server succeeded unexpectedly");
                            } catch (final ConnectionException ce) {
                                // This is expected - so go to online server.
                                try {
                                    lcf =
                                            new LDAPConnectionFactory(
                                                        onlineServerAddr.getHostName(),
                                                        onlineServerAddr.getPort());
                                    lcf.getConnection().close();
                                } catch (final Exception e) {
                                    // Unexpected.
                                    throw newLdapException(
                                                    ResultCode.OTHER,
                                                    "Unexpected exception when connecting to online server",
                                                    e);
                                }
                            } catch (final Exception e) {
                                // Unexpected.
                                throw newLdapException(
                                                ResultCode.OTHER,
                                                "Unexpected exception when connecting to offline server",
                                                e);
                                failOverToOnlineServer(onlineServerAddr);
                            } catch (final LdapException e) {
                                // The listener only closes the client connection when handleAccept
                                // fails: report the failure through the context the test waits for,
                                // instead of leaving that wait to time out without a cause.
                                proxyServerConnection.context.handleException(e);
                                throw e;
                            } catch (final RuntimeException e) {
                                proxyServerConnection.context.handleException(
                                        newLdapException(ResultCode.OTHER, e));
                                throw e;
                            }

                            return super.handleAccept(clientContext);
                        }

@@ -593,23 +606,28 @@
            final LDAPListener proxyListener = new LDAPListener(Collections.singleton(loopbackWithDynamicPort()),
                    new ServerConnectionFactoryAdapter(Options.defaultOptions().get(LDAP_DECODE_OPTIONS),
                            proxyServerConnectionFactory));
            // Connect to the proxy listener (not to the online server
            // directly, otherwise the proxy handleAccept is never invoked)
            // and close.
            final InetSocketAddress proxyAddr = proxyListener.firstSocketAddress();
            final LDAPConnectionFactory proxyClientFactory =
                    new LDAPConnectionFactory(proxyAddr.getHostString(), proxyAddr.getPort());
            try {
                // Connect to the proxy listener (not to the online server
                // directly, otherwise the proxy handleAccept is never invoked)
                // and close.
                final InetSocketAddress proxyAddr = proxyListener.firstSocketAddress();
                final Connection connection =
                        new LDAPConnectionFactory(proxyAddr.getHostName(),
                            proxyAddr.getPort()).getConnection();

                assertThat(proxyServerConnection.context.get(10, TimeUnit.SECONDS)).isNotNull();
                assertThat(onlineServerConnection.context.get(10, TimeUnit.SECONDS)).isNotNull();

                connection.close();
                final Connection connection = proxyClientFactory.getConnection();
                try {
                    // handleAccept makes both fail-over connections before it resolves the context,
                    // and each of them may take up to the default connect timeout (10 seconds):
                    // wait longer than that, so that a failed attempt reports its own cause.
                    assertThat(proxyServerConnection.context.get(30, TimeUnit.SECONDS)).isNotNull();
                    assertThat(onlineServerConnection.context.get(10, TimeUnit.SECONDS)).isNotNull();
                } finally {
                    connection.close();
                }

                // Wait for connect/close to complete.
                proxyServerConnection.isClosed.await();
                assertThat(proxyServerConnection.isClosed.await(10, TimeUnit.SECONDS)).isTrue();
            } finally {
                proxyClientFactory.close();
                proxyListener.close();
            }
        } finally {
@@ -624,7 +642,7 @@
     * @throws Exception
     *             If an unexpected exception occurred.
     */
    @Test(timeOut = 10000)
    @Test(timeOut = 60000)
    public void testLDAPListenerProxyDuringHandleBind() throws Exception {
        final MockServerConnection onlineServerConnection = new MockServerConnection();
        final MockServerConnectionFactory onlineServerConnectionFactory =
@@ -643,34 +661,22 @@
                        final IntermediateResponseHandler intermediateResponseHandler,
                        final LdapResultHandler<BindResult> resultHandler)
                        throws UnsupportedOperationException {
                    // First attempt offline server.
                    InetSocketAddress offlineAddress = findFreeSocketAddress();
                    LDAPConnectionFactory lcf = new LDAPConnectionFactory(offlineAddress.getHostName(),
                            offlineAddress.getPort());
                    try {
                        // This is expected to fail.
                        lcf.getConnection().close();
                        resultHandler.handleException(newLdapException(
                                ResultCode.OTHER,
                                "Connection to offline server succeeded unexpectedly"));
                    } catch (final ConnectionException ce) {
                        // This is expected - so go to online server.
                        try {
                            lcf = new LDAPConnectionFactory(onlineServerAddr.getHostName(),
                                onlineServerAddr.getPort());
                            lcf.getConnection().close();
                            resultHandler.handleResult(Responses.newBindResult(ResultCode.SUCCESS));
                        } catch (final Exception e) {
                            // Unexpected.
                            resultHandler.handleException(newLdapException(
                                    ResultCode.OTHER,
                                    "Unexpected exception when connecting to online server", e));
                        }
                    } catch (final Exception e) {
                        // Unexpected.
                        resultHandler.handleException(newLdapException(
                                ResultCode.OTHER,
                                "Unexpected exception when connecting to offline server", e));
                        failOverToOnlineServer(onlineServerAddr);
                        resultHandler.handleResult(Responses.newBindResult(ResultCode.SUCCESS));
                    } catch (final LdapException e) {
                        // A bind must fail with a bind result: the listener cannot encode any other
                        // result as a bind response, and would then never answer the bind. Only the
                        // diagnostic message reaches the client, so it carries the nested cause.
                        final Throwable cause = e.getCause();
                        final String message = cause != null
                                ? e.getResult().getDiagnosticMessage() + ": " + cause
                                : e.getResult().getDiagnosticMessage();
                        resultHandler.handleException(newLdapException(Responses.newBindResult(ResultCode.OTHER)
                                .setDiagnosticMessage(message).setCause(e)));
                    } catch (final RuntimeException e) {
                        resultHandler.handleException(newLdapException(Responses.newBindResult(ResultCode.OTHER)
                                .setDiagnosticMessage(e.toString()).setCause(e)));
                    }
                }

@@ -681,11 +687,11 @@
                    new ServerConnectionFactoryAdapter(Options.defaultOptions().get(LDAP_DECODE_OPTIONS),
                            proxyServerConnectionFactory));
            final InetSocketAddress proxyAddr = proxyListener.firstSocketAddress();
            final LDAPConnectionFactory proxyClientFactory =
                    new LDAPConnectionFactory(proxyAddr.getHostString(), proxyAddr.getPort());
            try {
                // Connect, bind, and close.
                final Connection connection =
                        new LDAPConnectionFactory(proxyAddr.getHostName(),
                            proxyAddr.getPort()).getConnection();
                final Connection connection = proxyClientFactory.getConnection();
                try {
                    connection.bind("cn=test", "password".toCharArray());

@@ -699,6 +705,7 @@
                // Wait for connect/close to complete.
                proxyServerConnection.isClosed.await();
            } finally {
                proxyClientFactory.close();
                proxyListener.close();
            }
        } finally {