Notice of Disconnection to an already-closed client is reported as an uncaught OnErrorNotImplementedException

[vharseko]

Problem

When the server drops a connection served by LDAPConnectionHandler2 and the client has already closed its socket, the failed Notice of Disconnection is reported as an unhandled RxJava error:

io.reactivex.rxjava3.exceptions.OnErrorNotImplementedException: The exception was not handled due to missing onError handler in the subscribe() method call. ... | java.io.EOFException
	at io.reactivex.rxjava3.internal.observers.EmptyCompletableObserver.onError(EmptyCompletableObserver.java:50)
	...
	at com.forgerock.reactive.RxJavaStreams$2$1.onError(RxJavaStreams.java:174)
	at org.forgerock.opendj.grizzly.LDAPServerFilter$ClientConnectionImpl$6$2.handleException(LDAPServerFilter.java:649)
	...
	at org.forgerock.opendj.grizzly.LDAPServerFilter$ClientConnectionImpl.disconnect(LDAPServerFilter.java:545)
	at org.forgerock.opendj.reactive.LDAPClientConnection2.disconnect(LDAPClientConnection2.java:666)
	at org.opends.server.core.AuthenticatedUsers.doPostResponse(AuthenticatedUsers.java:174)
	at org.opends.server.core.PluginConfigManager.invokePostResponseDeletePlugins(PluginConfigManager.java:3660)
	at org.opends.server.core.DeleteOperationBasis.invokePostResponsePlugins(DeleteOperationBasis.java:287)
	at org.opends.server.core.DeleteOperationBasis.run(DeleteOperationBasis.java:254)
	at org.opends.server.extensions.TraditionalWorkerThread.run(TraditionalWorkerThread.java:170)
Caused by: java.io.EOFException
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:575)
	...

Nothing is wrong with the connection: the client simply left first, and the server can no longer write to it. That is an expected situation, but it is reported as an uncaught exception.

Where it shows up

This shows up in the build-docker-alpine benchmark (.github/benchmark/compare-opendj.sh, "Build-alpine vs Release-alpine"). The server log of the image under test (a.docker.log in the benchmark-build-vs-release-alpine artifact) has 7 to 11 of these traces per run, for example:

Run	Traces
36776405938 (PR #1125)	7
36767616891 (PR #1142)	8
36766433743 (PR #1138)	11
36765936574 (PR #1137)	9

All 7 traces in run 36776405938 come from the same path: AuthenticatedUsers.doPostResponse after a DELETE.

The released image openidentityplatform/opendj:alpine (5.1.2) is affected the same way. Its shipped config.ldif already uses org.forgerock.opendj.reactive.LDAPConnectionHandler2 for the LDAP connection handler, and it has the same disconnect code and RxJava 3. Its container log (b.docker.log) shows no traces only because it stops after OpenDJ is started: the image does not stream the running server's output, not even the "Started listening" notices.

The benchmark hits it as follows:

1. The BIND sampler binds as mail=u_<thread>_<iter>@test.com,... on its own connection, then unbinds and closes it.
2. The DELETE sampler deletes that same entry on the admin connection.
3. The server sometimes runs the DELETE before it has processed the client's close. AuthenticatedUsers still lists the BIND connection and disconnects it with a notice (DisconnectReason.INVALID_CREDENTIALS, sendNotification = true).
4. The check !clientContext.isClosed() at LDAPClientConnection2.java:662 still passes, so the server writes the Notice of Disconnection to a socket the peer has already closed. Grizzly fails that write with EOFException.

Cause

LDAPServerFilter.ClientConnectionImpl.disconnect(ResultCode, String) (LDAPServerFilter.java:533-546) subscribes to the notification Completable without an error consumer:

sendUnsolicitedNotification(...)
        .doAfterTerminate(() -> connection.closeSilently())
        .subscribe();

The try/catch (OnErrorNotImplementedException) around s.onError(exception) at LDAPServerFilter.java:648-654 was meant to swallow this, but it never sees the exception. In RxJava 3.1.10, EmptyCompletableObserver.onError does not throw. It wraps the error in OnErrorNotImplementedException and passes it to RxJavaPlugins.onError. With no plugin error handler installed, that method:

• prints the stack trace to stderr (this is what lands in server.out / the container log), and
• passes it to the current thread's uncaught-exception handler. For a worker thread that is DirectoryThread.DirectoryThreadGroup.uncaughtException, which logs ERR_UNCAUGHT_THREAD_EXCEPTION and sends an ALERT_TYPE_UNCAUGHT_EXCEPTION alert notification. This step is based on reading the code. The errors log is not part of the benchmark artifact, so it has not been observed directly.

The try/catch at LDAPClientConnection2.java:663-671 does not help either, because the write fails asynchronously after disconnect(...) has returned.

So every time a client leaves just before the server would have dropped it, the server prints a stack trace and, according to the code, also raises an "uncaught exception" error and alert. Any alerting built on those will report false positives.

The other bare .subscribe() in the same class (LDAPServerFilter.java:210) is not affected: its stream ends in onErrorResumeWith(... emptyStream()), which swallows the error first.

Related: #317 (4.6.1) reported the same OnErrorNotImplementedException from LDAPServerFilter.disconnect and was answered with 4.6.2. The guard at LDAPServerFilter.java:648-654 came in with the RxJava 3 migration in #555.

Proposed fix

• Subscribe with an error consumer in ClientConnectionImpl.disconnect(ResultCode, String), using the existing Completable.subscribe(Action, Consumer<Throwable>). Trace the failure with logger.traceException(...): a peer that is already gone is expected here. Keep doAfterTerminate(connection.closeSilently()) so the socket is still closed on both outcomes.
• Remove the dead try/catch (OnErrorNotImplementedException) at LDAPServerFilter.java:648-654.
• Add a test: disconnect with a notice on a client context whose peer has already closed. The test should check that nothing reaches RxJavaPlugins.onError (install a capturing handler for the test) and that the connection ends up closed.