[#1245] Do not report a peer as badly disconnected when a ServerWriter fails to write to a session this side has closed (#1248)
Fixes #1245
## What
`ServerWriter.run()` now logs the badly-disconnected message (msgID 211
for a directory server, 181 for a replication server) on a
`SocketException` only when the handler is not shutting down and the
close of the session was not initiated on this side:
```java
if (!handler.shuttingDown() && !session.closeInitiated())
{
errMessage = handler.getBadlyDisconnectedErrorMessage();
logger.error(errMessage);
}
```
## Why
On a replication server the session runs the publisher thread that
`ServerHandler` starts. While it runs, `publish()` only queues, and when
a write of that thread fails, the failure never reaches the writer. The
writer gets a `SocketException` once a close has taken the session off
that thread, and that close is made on this side:
- `ServerReader`, once the peer has sent its `StopMsg`;
- `ServerReader`, once its read has failed;
- a shutdown of the handler.
So a peer that left in order under load was reported as badly
disconnected, at ERROR, whenever the writer had an update for it at that
moment. That covers a directory server that was stopped or moved by the
load balancing, and a replication server that was stopped. The issue
lists the records from the convergence run, on master and on PR #1244.
The two checks are the ones the other ends already make:
- `ServerReader` checks `handler.shuttingDown()` before the same
message. That flag alone would not cover the writer: the `finally` of
the reader closes the session before `handler.doStop()` sets it.
- The directory server end checks `Session.closeInitiated()` in
`ReplicationBroker.receive()` before
`WARN_REPLICATION_SERVER_BADLY_DISCONNECTED`.
How a connection ended is reported by the reader, as before. A read that
fails on the socket is reported as a bad disconnection, at ERROR. The
writer reports a failing write only on a session whose publisher thread
is not running, and a replication server session runs it from the start.
A peer that goes away without a `StopMsg` leaves an end of the stream,
and the reader reports that only at NOTICE (`NOTE_READER_EXCEPTION`,
msgID 53). Such a peer is older than protocol V4, was killed with
nothing left unread, or gave up a session that had failed. Before this
change the writer added a 211 or 181 at ERROR whenever it had an update
for that peer, which is the same race. Now the NOTICE is all there is.
Whether the reader should report an end of the stream as a bad
disconnection is #1250. It is left out of this PR because it changes
what is logged for an idle peer as well.
## Testing
`ServerWriterDisconnectTest` (new) runs a writer on the thread of the
test. It uses a session over the loopback and a mocked handler that
hands the writer one update, then checks what the writer logged when the
write of that update failed:
| case | the session | expected |
|---|---|---|
| `aWriteFailingOnASessionThisSideClosedIsNotReported` | publisher
thread started, then closed, as `ServerReader` closes it on a `StopMsg`
| no 211 |
| `aWriteFailingOnASessionClosedAfterItsReadFailedIsNotReported` |
publisher thread started, the sockets of the peer closed without a
`StopMsg`, `receive()` failing on it, then closed, as the `finally` of
`ServerReader` closes it | no 211 |
| `aWriteFailingOnASessionNothingClosedIsReported` | publisher thread
not started, its sockets closed under it | one 211 |
| `aWriteFailingWhileTheHandlerShutsDownIsNotReported` | publisher
thread not started, its sockets closed under it, the handler shutting
down | no 211 |
The third case is in a state a replication server session never reaches,
because its publisher thread runs from the start. It keeps the guard
from being one that never reports.
Each case also checks that the writer got as far as the write
(`countSentUpdate`) and that the write failed (`take()` is called once).
It also checks that the writer stopped the handler, and that the write
failed on the socket and not on anything else (no
`ERR_WRITER_UNEXPECTED_EXCEPTION`). The records are read through a
publisher of the test's own (`errorLogRecordsOf`), so each record is one
line. None is deduplicated, so a 211 logged twice fails the third case.
Only the records of the `SYNC` category at ERROR are counted, because
the messages of other categories share the ordinals.
Locally, JDK 21, `mvn -o -Pprecommit verify -pl opendj-server-legacy -am
-Dit.test=ServerWriterDisconnectTest`. On `b76fa3619b`, with the test as
it is now:
- with the fix, 4 of 4 pass, the class in 12 s;
- with the 211 logged twice,
`aWriteFailingOnASessionNothingClosedIsReported` fails;
- with `ERR_WRITER_UNEXPECTED_EXCEPTION` also logged on the
`SocketException`, all four fail.
On `5055b6312f`, with the test before its last round (records collected
into a set, any category):
- with the `ServerWriter` of `origin/master`, 3 of 4 fail: the three
"not reported" cases get the 211;
- with `!session.closeInitiated()` dropped,
`aWriteFailingOnASessionThisSideClosedIsNotReported` and
`aWriteFailingOnASessionClosedAfterItsReadFailedIsNotReported` fail;
- with `!handler.shuttingDown()` dropped,
`aWriteFailingWhileTheHandlerShutsDownIsNotReported` fails.
The convergence run in CI is the end-to-end check. The `restart-ds` rows
fail on these records now, `combined` on master and `rs534` on PR #1244.