[#1241] Log the benign aborts of a replication handshake as warnings: the cross connection timeout (145) and a peer which went away (178, 179) (#1242)
Fixes #1241
## Problem
`ServerHandler.abortStart(LocalizableMessage)` logged the reason of
every aborted replication handshake through `logger.error`. Two kinds of
abort that are no error of this server came out at ERROR that way:
- msgID 145, `WARN_TIMEOUT_WHEN_CROSS_CONNECTION`: the listen thread
gives way to a cross connection on purpose. `lockDomainWithTimeout()`
threw it in a `DirectoryException`, and `startFromRemoteRS` passed it to
`abortStart` with the other `DirectoryException`s.
- msgID 178 and 179, `*_DISCONNECTED_DURING_HANDSHAKE`: an `IOException`
during the handshake, that is, the peer went away. A peer which gave up
on its own timeout logs that itself at WARNING (msgID 212), so one event
read as a WARNING on one side and an ERROR on the other.
A peer which restarts under load leaves both behind on every server it
was handshaking with (restart-ds rows of #1208, runs
[40463887505](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/40463887505)
and
[39909337627](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/39909337627)),
and an alert on `category=SYNC severity=ERROR` takes them for errors of
those servers.
## Fix
- `abortStart(reason)` still logs at ERROR. The new
`abortStartWithWarning(reason)` logs at WARNING; both run the same
private abort.
- `lockDomainWithTimeout()` returns whether it got the lock instead of
throwing. `startFromRemoteRS` aborts a timed out wait with
`abortStartWithWarning(WARN_TIMEOUT_WHEN_CROSS_CONNECTION)`, so the
`DirectoryException`s left in its catch are the rejections of this
server, still at ERROR.
- The three `IOException` catches of the handshake (`DataServerHandler`
and both directions of `ReplicationServerHandler`) abort with
`abortStartWithWarning`. In `DataServerHandler` the `IOException` is no
longer wrapped in a `DirectoryException` for the outer catch.
- A peer silent past the connection timeout fails `receive()` with a
`SocketTimeoutException`, an `IOException`, and is aborted on at WARNING
as well. In the first phase this is what the connect thread of a cross
connection reads while the listen thread of its peer waits up to 8 s for
the domain lock, against a connection timeout of 5 s by default. The
second phase used to log it as the raw "Read timed out" at ERROR.
- `waitAndProcessTopoFromRemoteRS()`, which reads the `TopologyMsg` of a
replication server in the second phase of the handshake, no longer wraps
an `IOException` of the session in a `DirectoryException`. A replication
server gone before it sent its topology was logged there as
`severity=ERROR msgID=-1 msg=no more data`; it is the 179 warning of the
first phase now.
- A frame too large to allocate is not the peer going away, though the
session reported it as an `IOException`. `Session.receive()` raises a
`PacketTooLargeException` for it, an `IOException` still for every other
caller, and the three catches abort on it ahead of their `IOException`
arm, at ERROR. The text is its own ("Packet too large, can't allocate N
bytes."), as the second phase of a replication server already logged it,
followed by the address of the peer (` Peer: host/ip:port`). Before this
PR the first phase and the handshake of a directory server logged that
frame under 178 or 179, which name the servers. `receive()` raises the
exception for any `OutOfMemoryError` while it reads or decodes a frame,
which is an error too.
- The keys of 178 and 179 are renamed from `ERR_` to `WARN_` in
`replication.properties` and in the five translations that have them
(de, es, fr, ja, zh_CN), as #906 did for 105. The message IDs and texts
stay as they are. The prefix is what the log message reference is built
from (`GenerateMessageFileMojo` lists the `ERR_` keys only), so the two
entries are removed from the committed `appendix-log-messages.adoc` as
well.
A protocol error (`ERR_REPLICATION_PROTOCOL_MESSAGE_TYPE`,
"StartSessionMsg required"), a rejection by this server, a frame which
does not decode, a frame too large to allocate and an unexpected
exception are still logged at ERROR.
## Tests
`HandshakeAbortSeverityTest` drives each handler on a TLS session pair
of its own and reads the severity off the error log record of the
reason. The peer goes away through `Session.abort()`: `close()` would
send a `StopMsg`, which is a silent abort.
- `aCrossConnectionGivenWayToIsAWarning`: the listen thread waits for
the domain lock while another thread holds it. 145 is at WARNING, and no
179 follows it.
- `aDataServerGoneDuringTheHandshakeIsAWarning`,
`aReplicationServerGoneDuringTheHandshakeItStartedIsAWarning`,
`aReplicationServerGoneDuringTheHandshakeThisServerStartedIsAWarning`:
the peer aborts its end of the session before a directory server
handshake, before a handshake the peer started and before one this
server started; 178, 179 and 179 at WARNING.
-
`aReplicationServerGoneBeforeItsTopologyInTheHandshakeItStartedIsAWarning`,
`aReplicationServerGoneBeforeItsTopologyInTheHandshakeThisServerStartedIsAWarning`:
the peer reads what the handshake sent, then aborts while its topology
is due; 179 at WARNING.
- `aDataServerSilentDuringTheHandshakeIsAWarning`,
`aReplicationServerSilentDuringTheHandshakeThisServerStartedIsAWarning`,
`aReplicationServerSilentBeforeItsTopologyInTheHandshakeItStartedIsAWarning`:
the handler's session gets a 500 ms timeout and the peer stays silent,
in each of the three `IOException` catches; 178, 179 and 179 at WARNING.
- `aPeerWhichBreaksTheProtocolIsStillAnError`: the peer answers the
start message of this server with a `TopologyMsg`.
`aPeerWhichSendsNoTopologyInTheHandshakeItStartedIsAnError` and
`aPeerWhichSendsNoTopologyInTheHandshakeThisServerStartedIsAnError`: the
peer sends its start message again where its topology is due.
`aDataServerWhichSendsNoStartSessionIsAnError`: a directory server sends
its start message again where its start session is due ("Protocol error:
StartSessionMsg required."). All four protocol errors are still at
ERROR.
- `aServerIdAnotherReplicationServerHoldsIsAnError`: a peer names the
server id of a replication server the domain holds a session with at
another address; `ERR_DUPLICATE_REPLICATION_SERVER_ID` is still at
ERROR.
-
`aFrameTooLargeForTheStartMessageOfTheHandshakeThisServerStartedIsAnError`,
`aFrameTooLargeForTheTopologyInTheHandshakeItStartedIsAnError`,
`aFrameTooLargeForTheStartSessionOfADataServerIsAnError`: the peer sends
the length header `7fffffff` where a message is due. The text is at
ERROR, it names the peer, and there is no 178 or 179.
- `aFrameWhichDoesNotDecodeInTheHandshakeThisServerStartedIsAnError`:
the peer sends a frame of one byte, a message type no message has, where
the answer to the start message of this server is due. `receive()` fails
with a `DataFormatException`, and the `catch (Exception)` of `connect()`
logs "received message with unknown type" at ERROR.
- Every case of a directory server also asserts that the thread of the
session was never started. Only `finalizeStart()` starts it, after the
handler is registered with the domain, so this checks that the handshake
ends at the abort. It reads the thread, not the domain: the reader of a
handler started on a closed session may already have unregistered it.
## Verification
- **Red, on master** (round 0): the four original warning cases fail
with `severity=ERROR` in the same records as in the CI runs above; the
protocol error case passes.
- **Red, on master** (round 2): 12 of the 18 cases fail. They include
the three silent peer cases: 178 and 179 at ERROR, and in the second
phase `severity=ERROR msgID=-1 msg=Read timed out` instead of 179. The
other six pass: the four protocol errors, the rejection and the frame
which does not decode, which master logs at ERROR as well.
- **Red, on the round 0 head:** 4 of the 13 cases fail. Both
`…GoneBeforeItsTopology…` cases fail with `severity=ERROR msgID=-1
msg=no more data`, and the start message and start session frame cases
fail with 179/178 at WARNING.
- **Red, on the round 1 head** (c16e47b27e): 3 of the 18 cases fail, the
three frame cases, on the record which does not name the peer.
- **Mutants**, the whole class each time; each fails only its own cases:
- logging every abort as a warning (round 0):
`aPeerWhichBreaksTheProtocolIsStillAnError`;
- no `return;` after 145: the cross connection case;
- either `DirectoryException` catch of `ReplicationServerHandler`
logging a warning: the `…SendsNoTopology…` case of its direction (and,
for `startFromRemoteRS`, the duplicate server id case);
- each of the three `PacketTooLargeException` catches removed: the frame
case of its handshake;
- the `IOException` wrapped again in `waitAndProcessTopoFromRemoteRS()`:
both `…GoneBeforeItsTopology…` cases;
- a `SocketTimeoutException` logged at ERROR, in each of the three
`IOException` catches: the silent peer case of that catch;
- no `return;` after the 178 warning of `startFromRemoteDS()`: the gone
and the silent directory server cases; no `return;` after its frame
error: the start session frame case. Both fail with `expected:<[NEW]>
but was:<[TERMINATED]>`: the handshake went on to `finalizeStart()`, and
the thread of the session had already ended by the time the case checked
it;
- "StartSessionMsg required" logged as a warning:
`aDataServerWhichSendsNoStartSessionIsAnError`;
- the `catch (Exception)` of `connect()` logging a warning:
`aFrameWhichDoesNotDecodeInTheHandshakeThisServerStartedIsAnError`.
- **Green:** reactor `-Pprecommit verify -pl opendj-server-legacy -am`
with `HandshakeAbortSeverityTest`, `HandshakeAbortRegistrationTest`,
`HandshakeAbortGenerationIdTest`, `ReplicationServerConnectFailureTest`
and `MultiHomedPeerTest`: 35 tests, no failure. The javadoc of
`opendj-server-legacy` builds with doclint on.
## Not covered
- The whole replication test package was not run locally; CI runs it.
- The `catch (Exception)` of
`ReplicationServerHandler.startFromRemoteRS()` is not pinned. A peer
reaches it only through a failure of the JDK: a topology without the
replication server which sent it fails on `getRsInfos().get(0)` with an
`IndexOutOfBoundsException`. That is a missing check from before this
PR, and a case would pin the text of the JDK.
- The `DirectoryException` catch of
`DataServerHandler.startFromRemoteDS()` is not pinned. The only reason
with a message that reaches it is `ERR_SESSION_STARTUP_INTERRUPTED`, a
thread interrupted in `finalizeStart()`. `ERR_RS_INVALID_INIT_STATUS` is
turned into a `DirectoryException` without a message by the inner `catch
(Exception)` and aborted silently, as it was before this PR.
- A replication server of an older version still logs 145, 178 and 179
at ERROR, so a topology that mixes versions keeps them until every
server runs this one.
- Once this is merged, #1233 no longer needs to let 145, 178 and 179
through in its restart window.