[#911] Report the replication connections which used to be dropped in silence - #935
Conversation
…sed to be dropped in silence
maximthomas
left a comment
There was a problem hiding this comment.
praise: The diagnosis is right and the shape of the fix is right. Three give-up paths with three
different trigger natures get three different disciplines instead of one blanket rate limit: a time
window where the trigger is external and unbounded (accept, session setup), an edge-triggered
per-outage record where "peer is down" is a state (RS→RS connect), and the existing connectionError
latch on the DS side. Specific things worth keeping:
- Extracting #906's throttle into
FailureLogThrottleinstead of copy-pasting a second pair of
AtomicLongs. Verified byte-for-byte behaviour-preserving against the original, and
ReplSessionSecurityTestneeded no edit. - The backoff fires only on a repeated
accept()failure. Better than an unconditional sleep — a
loneECONNABORTEDno longer delays the connections queued behind it — and simpler than an
exponential backoff, which would need reset state on the success path. close(session)in the outercatchofrunListenis a real leak fix, and it is safe:
startFromRemoteDS/startFromRemoteRSboth terminate incatch (Exception)and never propagate,
so a session owned by a registered handler cannot reach it.Sessionis declared inside the
while, so no cross-iteration close either.- Correcting the "logged at debug level" wording in message 105 and the troubleshooting chapter.
logger.debug(LocalizableMessage)really does publish to the error log atINFORMATION, and the
shippedconfig.ldifreally does list onlywarning/error/notice. Good catch on someone
else's prose. connectionError's set/reset points are untouched, sopublish()'s message-dropping behaviour is
not widened by a logging change. Easy to get wrong; it wasn't.
issue (blocking): connect() clears the outage record without connecting, so the recovery notice
it promises is never logged.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:718
if (connectFailures.recordSuccess(remoteServerAddress, baseDN)
&& isConnectedToRS(remoteServerAddress, baseDN))&& evaluates left first, and recordSuccess mutates — it removes the DN from the peer's failure
set regardless of whether a connection exists.
Pass N: peer down, warning 312, whose text promises the next message comes when the connection is
established. Pass N+1: peer is back and dialled us simultaneously, so
ReplicationServerHandler.connect() takes the "Simultaneous cross connect." path —
abortStart(null); return;, no throw. connect() returns true, the record is erased,
isConnectedToRS is false, nothing is logged. Pass N+2: the already-connected branch at :744
calls recordSuccess again, gets false, and NOTE_REPLICATION_SERVER_CONNECT_RESTORED_313 never
fires. The outage opens in the log and never closes.
if (isConnectedToRS(remoteServerAddress, baseDN)
&& connectFailures.recordSuccess(remoteServerAddress, baseDN))The comment's worry — a record nothing clears — doesn't follow: the record only survives while the
peer is never seen connected under that address, and then the outage really hasn't ended. The cost
argument is thin too: connect() runs only for peers that are not connected, and
getConnectedRSAddresses(domain) is built once per domain per pass anyway.
todo (blocking): the reporter needs one test that goes through ReplicationServer.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ConnectFailureReporterTest.java:23
The only mention of ReplicationServer in the file is the import. No server is constructed;
connect(), runConnect() and reportConnectionRestored() are never called. All seven tests pass
with every call site deleted — which is exactly why the blocking issue above is invisible to them.
A unit test of the nested class structurally cannot catch a bug in how the nested class is called.
suggestion (non-blocking): three more assertions while you are in there.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerDynamicConfTest.java:597
opendj-server-legacy/src/test/java/org/opends/server/replication/ReplicationBrokerConnectFailureTest.java:67
Each of these currently ships green:
- Delete
if (repeated)so every accept failure sleeps 100 ms. OnlyacceptNanos[2] - acceptNanos[1]
is asserted; the first interval — the one that must not wait — is never computed. - Swap or hard-code
logThrottledFailure's two count arguments. Records are matched by substring and
severity=WARNINGand then counted; no assertion reads the number out of the message text. - Turn the new
logger.warn(errorMessage)intologger.error.ReplicationBrokerConnectFailureTest
asserts no severity at all — and that split is the decision the PR body argues for.
issue (non-blocking): per-(peer, baseDN) reporting is degenerate — one domain is ever reported
per peer.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:592
runConnect() loops domains-outer / peers-inner. domainTicket increments once per outer pass
(:614 is the only ++), so it is constant across all domains of a pass, and the blacklist is keyed
by address alone while the reporter is keyed by (address, baseDN):
if (blacklistedHosts.getOrDefault(rsAddress, 0L) > domainTicket) { continue; } // :592
...
if (!connect(rsAddress, domain.getBaseDN())) {
blacklistedHosts.put(rsAddress, domainTicket + 6); // :600
}Peer P down, domains A/B/C: pass 0 connect(P,A) fails → warning 312 → put(P,6), B and C skipped.
Passes 1–5 skipped entirely. Pass 6 connect(P,A) fails → recordFailure returns false → no log.
After ten passes: one DN in the set, one warning line, connect() called twice, both for A. A always
fails first and re-blacklists the address before B and C are reached, and baseDNs is a plain
HashMap that doesn't change during the outage, so the same domain wins every pass. The operator
reads "could not connect … for domain A" and concludes B and C are fine.
The blacklist is pre-existing and untouched by this diff, so this is inherited, not introduced — not
worth blocking on. But the PR shouldn't ship a message implying coverage it doesn't have. Cheapest
honest fix: key the reporter by peer only and drop baseDN from messages 312/313. Real per-domain
reporting needs Map<HostPort, Map<DN, Long>>, which belongs in its own issue.
suggestion (non-blocking): a full stack trace at WARNING, once per contacted replication server,
on the one path left unthrottled.
opendj-server-legacy/src/main/java/org/opends/server/replication/service/ReplicationBroker.java:1164
errorMessage = WARN_EXCEPTION_STARTING_SESSION_PHASE.get(
getServerId(), serverURL, getBaseDN(), stackTraceToSingleLineString(e));The fourth %s of message 119 is the whole trace on one line. createClientSession (:1095) throws
SSLException, which is neither ConnectException nor SocketTimeoutException, so it lands here
with hasConnected == false and goes out through the new logger.warn at :1206. One bad
certificate among three RSs with the elected session flapping: connectionError stays false, an
SSL failure is fast (no 5 s connect timeout to pace it), and collectReplicationServersInfo() reruns
over every URL per reconnect — one full stack trace per flap cycle.
Before this PR the same trace reached logger.error only for the elected server. Pass
getExceptionMessage(e) on the warn branch and keep the trace for the elected one, or route this
message through the FailureLogThrottle the PR already adds. Every other new message here is
throttled; this one isn't.
Note the neighbouring claim does not hold and is not part of this: the new per-RS warning is not
unbounded per flap — one extra line per pass, zero while stably connected, and each flap cycle
already logs BADLY/PROPERLY_DISCONNECTED.
suggestion (non-blocking): the accept throttle outlives the listen thread it rate-limits.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:166
acceptFailures is an instance field with one unkeyed lastLogNanos; the backoff clock beside it,
lastAcceptFailureNanos (:339), is a runListen local — documented as thread-confined precisely
because a port change runs a second listen thread. Two scopes for the same event.
Server out of file descriptors, accept fails and warns at T. Admin changes the listen port at T+30s.
The new thread's first accept failure gets a negative record() and goes to logger.debug (:542) —
Severity.INFORMATION, unpublished by the shipped config. Silence on the new port for up to five
minutes, right after the admin changed it to get out of trouble.
Make the throttle a runListen local next to lastAcceptFailureNanos — same scoping the code already
chose for the backoff clock, one field-to-local move — or key it by socket address. (The mechanism is
the 5-minute state surviving the handover, not the microsecond thread overlap; and the record does name
the new port correctly, so the operator is under-informed rather than misled.)
nitpick (non-blocking): the new warn branch publishes an ERR_-named message at WARNING.
opendj-server-legacy/src/main/java/org/opends/server/replication/service/ReplicationBroker.java:1206
The comment above says contacted servers are reported as "the warnings their messages are named for".
Three of the four errorMessage sources are WARN_; ERR_DS_DN_DOES_NOT_MATCH at :1124 returns
without setting hasConnected (only :1141 does), so it reaches the finally with
keepSession == false and goes out at WARNING. It's the only ERR_-named message that can.
A base-DN mismatch is a permanent misconfiguration, not a transient — it's the one condition here
that won't fix itself, and it's the one getting the softer severity. Either log it at error like its
name says, or amend the comment to say the branch is severity-by-role rather than
severity-by-message-name.
Not a downgrade, to be clear: before this PR that path logged nothing above trace.
todo (non-blocking): the doc's dsconfig instruction names a value the configuration rejects.
opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc:799
add
informationto thedefault-severityproperty of the error log publisher to see them
The enumeration is {all, debug, error, info, none, notice, warning}. information is not in it, so
dsconfig set-log-publisher-prop --add default-severity:information is rejected — and this is the
only actionable instruction the PR gives for reaching the suppressed records.
The token is info. It does map to Severity.INFORMATION (Severity.java:43 declares
INFORMATION("INFO"), and TextErrorLogPublisher:426 resolves it via
Severity.parseString(defSev.name())), so the mechanism is right and only the word is wrong. The
surrounding prose and messages 105/310/311 are correct as they stand — they name the severity, not a
config value.
…and test the reporting through the server Read the session before clearing the record of an outage: abortStart() closes it to abort a handshake and a completed one leaves it open, so an open session is the connection which ends the outage. recordSuccess() mutates, so clearing first cleared the record of a peer the pass did not connect to, and the outage was then reported open and never reported closed. Read from the session rather than from the registration with the domain, which a peer negotiating protocol V1 -- or one whose handler advertises an address which does not resolve to the configured one -- never gets, and whose record would then never be cleared at all. Time the accept backoff from the previous failure being handled rather than from the failure itself, so that the wait one failure was granted does not make the next look isolated: half of a continuous run went unwaited, at twice the intended rate. Reset it on a successful accept, so that a stream of connections aborted before accept() -- a health check, a port scan -- does not charge the listen port a wait per probe. Say where the suppressed records are, rather than that they are nowhere: the shipped replication log publisher overrides the information severity on for the SYNC category, so it holds one record per failure while the error log holds the throttled warnings. Messages 105, 310 and 311, the sample quoting 105, the ReplSessionSecurity javadoc and the troubleshooting chapter all claimed the opposite, three paragraphs under the line which names logs/replication. Add ReplicationServerConnectFailureTest, which drives the reporting through ReplicationServer instead of through the bookkeeping alone: a peer which stops the handshake with a StopMsg, and two replication servers whose connect threads report an outage and its end. Both configure the peer they drive and create the domain they drive it for, and the one which records from the test thread waits a whole pass of the connect thread, because runConnect() runs retainAll against the domains its pass snapshotted. Pin what the accept path only appeared to test: that the first failure of a row is not waited on and every later one is, and which of the two numbers in its message is the suppressed count. Assert the severity of a cause reported for a replication server which was only contacted. Pass the session phase failure as a message rather than a stack trace on the branch which is not throttled, keeping the trace for the server the broker elects. Scope the accept throttle to the listen thread, so a port change does not inherit its window. Read the listen address before the socket is tested, so a port change does not report it as null. Say in message 312 that the domain named is the one the attempt was for, and name the severity value the configuration accepts.
|
Addressed in 8b3c4af. Both blocking items are fixed, and the diagnosis behind the first one turned out to reach further than the ordering. issue (blocking):
|
| mutation | now fails with |
|---|---|
delete if (repeated) |
104661 microseconds passed between the first attempt and the second |
swap logThrottledFailure's two count arguments |
the record must read every 5 minutes and (N since the previous warning) |
logger.warn(errorMessage) → logger.error |
[the cause of a replication server which was only contacted is a warning] |
Reading the counts out of the message text turned up a fourth thing, below.
issue (non-blocking): per-(peer, baseDN) reporting is degenerate
The mechanism is exactly as you describe: domainTicket increments once per pass at :614, the blacklist is keyed by address, so connect(P, A) failing re-blacklists P before B and C are reached, and the same domain wins every pass.
I did not key the reporter by peer and drop the domain, because that regresses the mixed case. If P is reachable for domain A and fails for domain B — connect(P, A) succeeded, so A stays in connectedRSAddresses — then with peer-only keying recordFailure(P) from B and reportConnectionRestored(P) from the already-connected branch of A alternate, and the log gets a 312/313 pair every time the blacklist expires. The current Map<HostPort, Set<DN>> is stable there. So I fixed what the message claims instead: 312 now says the domain named is the one the attempt was for and that an unreachable peer is not tried for its other domains while it cannot be reached, and the troubleshooting chapter says the same. Real per-domain reporting still wants its own issue, and it wants the blacklist keyed by (address, baseDN) more than it wants a different map.
suggestion (non-blocking): a full stack trace at WARNING on the unthrottled path
Fixed. keepSession is already the discriminator the finally uses, so it picks the detail at build time:
errorMessage = WARN_EXCEPTION_STARTING_SESSION_PHASE.get(getServerId(), serverURL, getBaseDN(),
keepSession ? stackTraceToSingleLineString(e) : getExceptionMessage(e));The elected server keeps the trace it carried before this PR; the ones only contacted get the message, and traceException(e) above still puts the trace in the trace log. I also corrected the comment's volume claim while I was there — it said "as often as the reconnection itself is reported", but it is one line per unreachable server per reconnection, not one line per reconnection.
suggestion (non-blocking): the accept throttle outlives the listen thread
Fixed — acceptFailures is now a runListen local next to lastAcceptFailureNanos, passed to handleAcceptFailure, exactly the scoping the backoff clock already had.
Two more things on that path, both mine:
- The backoff was granted to every second failure of a continuous run.
lastAcceptFailureNanoswas stamped at the failure, so after a 100 ms sleep the next failure was 100 ms away from the stamp and read as isolated. Measured: the third failure of a row waited 552 µs instead of 100 ms, so the spin was bounded at twice the intended rate. It is now stamped after the failure is handled, and the accept test runs four failures so that two waits in a row are measured. - A successful
accept()now puts that clock back a whole interval. Without it, a stream of connections aborted between the handshake andaccept()— a health check, a port scan — would charge the listen port a wait per probe and make the peers queued behind them pay it. socket.getLocalSocketAddress()is read before theisClosed()guard rather than after it: a socket closed in between made the warning name the port asnull.
nitpick (non-blocking): an ERR_-named message at WARNING
The reading is right — ERR_DS_DN_DOES_NOT_MATCH is set at :1124 without setting hasConnected, which is only set at :1141, so it is the one ERR_ which can reach the warn branch.
I took the second option and amended the comment rather than special-casing the message. The branch's rule is severity by role — the server this broker is electing is the one it cannot work without, so its failure is an error; a server which was only contacted is a warning because the broker found another one. Adding an exception would make the rule "by role, except this one message", which is harder to keep true than to state. A base DN mismatch on the elected server still goes out as an error, and on a contacted one the path logged nothing above trace before this PR.
todo (non-blocking): the doc names a value the configuration rejects
Fixed: info, not information. The enumeration in ErrorLogPublisherConfiguration.xml is {all, none, error, info, warning, notice, debug} and Severity.parseString("INFO") resolves to INFORMATION, so the mechanism was right and only the token was wrong.
Found while re-reading that paragraph: the throttle bounds logs/errors, not logs/replication
The wording those three messages share — "the others are recorded with the information severity, which the error log does not publish by default" — is true of logs/errors and misleading about everything else. cn=Replication Repair Logger ships enabled with
ds-cfg-log-file: logs/replication
ds-cfg-default-severity: none
ds-cfg-override-severity: SYNC=INFO,ERROR,WARNING,NOTICE
LoggingCategoryNames maps org.opends.messages.replication to SYNC, and TextErrorLogPublisher.isEnabledFor prefers definedSeverities.get("SYNC"), which holds INFORMATION. So the suppressed records are published, to logs/replication, one line per failure — and the paragraph telling the reader to add info to the error log publisher "to see them" sits three lines under the line which says replication has its own log file. That is the contradiction on one page this PR set out to avoid, shipped by the PR itself.
Messages 105, 310 and 311 now say the information severity is "which the replication log publishes and the error log does not", the sample quoting 105 was rewrapped to match, the troubleshooting paragraph says where the records are before it says how to get them into the error log as well, and the ReplSessionSecurity javadoc which still said "at debug level" was corrected the same way. Message 105 and its sample are #906's, but this PR had already re-worded them, so leaving them would have shipped the contradiction under a corrected line.
Verified
mvn -Pprecommit -pl opendj-server-legacy verify over 15 classes — 85 tests, no failures:
FailureLogThrottleTest,ReplSessionSecurityTest,ConnectFailureReporterTest,ReplicationServerConnectFailureTest,ReplicationBrokerConnectFailureTest,ReplicationServerDynamicConfTestCryptoManagerTestCase,GroupIdHandshakeTest,ReplicationServerFailoverTest,TopologyViewTest,HandshakeAbortGenerationIdTest,HandshakeAbortRegistrationTest,ReplicationServerShutdownSyncTest,ReplicationServerTest,DSRSShutdownSyncTest
HandshakeAbortRegistrationTest and GroupIdHandshakeTest were run on their own: in a long run they collide on the administration connector port, which is the harness rather than this change.
What the new tests pin, and what they do not: the abort test fails on the ordering, the accept test fails on any of the three mutations above and on the backoff timing, and the two-server test fails if 312 or 313 stops being emitted. Still not pinned: message 311, and the call site of reportConnectionRestored inside runConnect() as opposed to the method itself.
maximthomas
left a comment
There was a problem hiding this comment.
praise: The second round answers every item, and three of the answers are better than what was
asked for. Verified this round:
- The V1 half of the argument for reading the session instead of the registration is correct.
ReplicationServerHandler.connect()registers only inside the> REPLICATION_PROTOCOL_V1branch
(ReplicationServerHandler.java:242), so keying on the registration really would have left a V1
peer's record uncleared for good. Declining the operand swap was right. keepSession ? stackTraceToSingleLineString(e) : getExceptionMessage(e)reuses the discriminator
thefinallyalready has — no new state, and the elected server keeps the trace it had.- Stamping the backoff clock after the failure is handled rather than at the failure is a real
defect found and fixed unprompted, and the accept test now runs four failures so two consecutive
waits are measured rather than one. - Moving
acceptFailuresintorunListenis the right scoping:switchListenPort()calls
startListenThread()at:1055beforestopListenThread()at:1065, so the two listen threads
genuinely overlap. - The
logs/replicationfinding is the best thing in the round.cn=Replication Repair Logger
ships withds-cfg-override-severity: SYNC=INFO,..., so the suppressed records are published;
correcting 105/310/311 rather than shipping the contradiction was the right call even though 105
is #906's. - The mutation table holds.
if (true)atReplicationServer.java:760reproduces verbatim:
aHandshakeThePeerAbortsLeavesTheOutageOpen:208,expected:<1> but was:<2>. - Message ordinals are clean: nothing renumbered or reused, and the placeholder count, type and
order of 105/310/311/312/313 match every call site. - The 158 lines added to
ReplicationTestCaseare purely additive across its 49 subclasses — no
field, no@BeforeClass, nothing widened. - The accept timing assertion is not tight:
firstIntervalNanosmeasured at 299/365/539 us against
a 100 ms bound over three invocations.
issue (blocking): on a multi-homed or NAT peer the record is now never cleared, so the peer's
next real outage is not logged at all.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:760
An outage is closed in two places: !session.closeInitiated() here, and the already-connected
branch of runConnect() at :601. That branch compares the configured rsAddress against
HostPort.valueOf(rsHandler.getServerAddressURL()), and the URL is socket-derived:
// ServerHandler.toServerAddressURL
new HostPort(session.getRemoteAddress().getHost(), port) // host from plainSocket.getInetAddress()The inbound handler therefore learns the peer's source IP, the outbound one the IP we dialled,
and HostPort.equals compares normalizedHost = InetAddress.getByName(host) — the first address
only. isEquivalentTo (getAllByName, overlap) exists but is not used here.
Peer P is configured as A1 and dials out from A2. P goes down, 312 is recorded. P returns and its
inbound connection wins the race, so startFromRemoteRS registers it as A2:port. From then on,
every pass:
runConnect():601misses (A2 vs A1), so the restore is never reported there;connect()runs, andReplicationServerHandler.connect(DN, boolean):188finds the handler but
"A2:port".equals("A1:port")is false, soisAlreadyConnectedToRSthrows
ERR_DUPLICATE_REPLICATION_SERVER_ID— caught at:265,abortStart,session.close()
(ServerHandler.java:231),closeInitiated()true,:760does not clear;connect()returnstrue, so no blacklist, and this repeats about once a second.
recordSuccess is reachable only from :607 and :762, both blocked; retainAll keeps the key
while the peer stays configured. The next real outage hits recordFailure at :828, which returns
false, and message 312 is never logged again. Round 1's code (f17fd3ee2f:718) evaluated
recordSuccess first and did clear the record here, so this half is a regression introduced by
the delta rather than an inherited defect.
The comment at :755-758 asserts the opposite for exactly this case — "and its session is open
here as well". In the multi-homing shape the session at :760 is closed.
Cheapest fix is to drop the second condition. connect() returns without throwing only after
createClientSession and the start-message exchange succeeded, so the peer is provably reachable
and the outage is over whatever the handshake did next:
if (connectFailures.recordSuccess(remoteServerAddress, baseDN))
{
logger.info(NOTE_REPLICATION_SERVER_CONNECT_RESTORED, getServerId(), remoteServerAddress, baseDN);
}That covers the round-1 bug, the V1 peer and the multi-homed peer at once, and depends on neither
the registration nor an address match. Keeping "an aborted handshake is not a connection" instead
means fixing runConnect():601 to use isEquivalentTo — more expensive, and still holed on NAT.
todo (blocking): the two new tests pin only the negative direction.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerConnectFailureTest.java:204
Measured at 8b3c4afb52 with
mvn -Pprecommit -pl opendj-server-legacy verify -Dit.test=ReplicationServerConnectFailureTest:
mutation of ReplicationServer.java:760 |
result |
|---|---|
if (true) — the pre-fix behaviour |
killed: :208, expected:<1> but was:<2> |
if (false) — connect() can never report a restore |
survived, both tests green |
the round-1 form isConnectedToRS(...) && recordSuccess(...) |
survived, both tests green |
So the suite certifies one proposition — an aborted handshake must not clear the record — and
cannot tell the shipped design from the one it replaced. if (false) survives because
aHandshakeThePeerAborts... asserts the restored count is zero, and aPeerWhichIsDown... takes its
single 313 from runConnect():607 instead. The round-1 form survives because both peers in that
test are real V2+ servers that do register. Every argument the design rests on — V1 peers,
multi-homed advertised addresses — is untested, and the issue above lives in that gap: broken and
working code pass identically.
Two cases close it, and both are small:
- Continue
aHandshakeThePeerAbortsLeavesTheOutageOpenwith the same fake peer completing the
handshake on a third connection, and assert exactly one 313. That peer is not configured as an
RS, sorunConnect():607cannot reach it and onlyconnect()can report — which kills
if (false)and closes the call site you listed as unpinned. - Have the fake peer answer with a
ReplServerStartMsgnaming an address other than the one it was
dialled on. That alone makesconnectedRSAddressesmiss, separates the two designs, and doubles
as the regression test for the issue above.
issue (non-blocking): round-1 item 7 was fixed for one of the two throttles.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:166
acceptFailures became a runListen local; sessionSetupFailures, added by this same PR, is still
an instance field. Its only reader is logSessionSetupFailure() at :523, whose only caller is
runListen() at :392 — used per listen thread, scoped per server. Since switchListenPort()
starts the new thread at :1055 before stopping the old one at :1065, the scenario the comment at
:345 describes applies verbatim: an ads-truststore made unreadable warns 311 at T, the admin
changes the listen port at T+30s, and the new thread's first failure is suppressed by the window
opened on the abandoned port — up to five minutes of silence in logs/errors right after the port
change. One field-to-local move, exactly as handleAcceptFailure already takes its throttle.
Worth noting while you are there: git grep sessionSetupFailures\|WARN_REPLICATION_SERVER_SESSION_SETUP_ERROR
over opendj-server-legacy/src returns the two main-source lines and the properties entry and
nothing else, so 311's argument order and the throttle have no test at all.
suggestion (non-blocking): the reset on a successful accept() reverses the rule the previous
round endorsed, without saying so.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:376
// A connection served is not a spin: the failures before it stop pacing the loop.
handledAcceptFailureNanos = System.nanoTime() - ACCEPT_FAILURE_BACKOFF_NANOS;The comment this delta deleted argued the other way: "a socket which frees a descriptor now and
then lets an accept through between two failures, and counting only consecutive ones would let that
alternation spin". The new line is that alternation: under descriptor exhaustion a freed descriptor
lets one connection through, repeated is false at the next failure, and the 100 ms is never taken
while the throttle still holds the error log to one line per five minutes.
The trade is defensible — a port scan should not charge the listen port a wait per probe — but the
reply presents it as pure gain. Nothing tests it either way: the only runListen test installs a
socket whose accept() throws on every call (ReplicationServerDynamicConfTest:568), so line :376
never executes and can be deleted or inverted with no assertion moving. Either say in the comment
what the reset gives up, or let the accept test succeed once between two failures and pin that no
wait follows it.
… what the handshake did next Clear the record of a peer whenever connect() reaches its end. Reading the session first closed the outage only for a handshake which completed, and a peer which dials out from an address other than the one it is configured under never completes one: ServerHandler.toServerAddressURL() registers its inbound handler under the source address of its own connection, so runConnect() compares the configured address with one it never matches, and the handshake this server offers that peer aborts on a duplicate server id, which closes the session. Nothing then cleared its record, and the next real outage of it was not reported at all. The outage is a failure to connect, and WARN_REPLICATION_SERVER_CONNECT_ERROR is reported for the socket and the session alone, ReplicationServerHandler.connect() throwing nothing of its own. So a peer which answered on its replication port is a peer this server can reach, whatever the handshake did next, and what the handshake did has messages of its own. reportConnectionRestored() clears the record and reports the recovery together, so an outage cannot be closed in the record without being closed in the log -- which is the shape the first round of this got wrong. Scope the session setup throttle to the listen thread, the way the accept throttle already is: switchListenPort() starts the new listen thread before it stops the old one, and a five minute window opened on the port which was left would suppress the first failure on the port which replaced it. Say what resetting the accept backoff on a served connection gives up: a process out of file descriptors frees one now and then, the accept it lets through resets the clock, and the failure behind it is timed as isolated. Pin all of it. A peer which stops the handshake and a peer which advertises an address it was not dialled on both close their outage and report it, and both fail if the recovery is read from the session, from the registration or from the address. The failure which follows a served connection is not waited on, and the connection served is one no session can be started on, which is what message 311 and the order of its arguments are read from.
|
Addressed in issue (blocking): the record is never cleared for a multi-homed peerConfirmed, and confirmed as mine rather than inherited: The chain holds link by link. The comment at :755-758 was wrong where you say it is, and worse than wrong — it fused two peers into one sentence. "A peer whose handler advertises an address which does not resolve to the configured one … is the same shape, and its session is open here as well": the V1 peer's session is open here, which is why reading the session survived it, and the multi-homed peer's is not. They are the same shape only with respect to the registration. Took the fix as written; the second condition is gone. reportConnectionRestored(remoteServerAddress, baseDN);
return true;This does not bring round 1's bug back, and the reason is structural rather than a promise. Round 1's bug was a record cleared without the recovery being logged — What makes it right rather than merely safe is the symmetry with the message it closes. Two costs, on the record rather than found later:
todo (blocking): the two new tests pin only the negative directionConfirmed; your table reproduces.
The second case is Measured with
Both failures of the first two read the same way, which is the point of the shape: Not taken: continuing the abort test with the same peer completing the handshake on a third connection. Under the fix there is no third state left to reach — the StopMsg connection is the one which closes the outage, so it already kills issue (non-blocking): round-1 item 7 was fixed for one of the two throttlesFixed. Message 311 has a test as well, which it did not: the new accept test below serves one connection no session can be started on, and reads the record back — the peer address rather than the listen port, and which of the two numbers is the interval and which is the count. suggestion (non-blocking): the reset reverses the rule the previous round endorsedTook both halves rather than one. The comment now says what the reset gives up: under descriptor exhaustion a freed descriptor lets one connection through, the failure behind it is timed as isolated, and the loop turns as fast as the connections arrive — against which the warning stays throttled to one line per five minutes either way. And Verified
|
maximthomas
left a comment
There was a problem hiding this comment.
praise: The fix is taken where it should be. reportConnectionRestored() clearing the record and logging 313 in one step makes "cleared but not reported" inexpressible at that call site — the round-1 bug is structurally gone, not merely avoided.
The mutation table reproduces. Measured in an isolated worktree at 8a38745d36, mvn -Pprecommit -pl opendj-server-legacy -am -Dit.test=ReplicationServerConnectFailureTest verify: baseline 3 cases pass; reportConnectionRestored(...) deleted — killed, 2 of 3 cases; the round-2 form if (!session.closeInitiated()) restored — killed, the same 2 cases, verbatim the same assertion text. The mutant that survived at the round-2 head is dead. Round-2 blocker 2 is closed.
listenThreadDoesNotWaitAfterAFailureWhichFollowedAConnection holds on both claims. Its record filter "accepted a connection from " + servedAddress belongs only to message 311 — 310 reads "could not accept a connection on" — and the address asserted is the served peer's, not the listen port, so substituting the listener's address gives zero matches. contains("every 5 minutes") && contains("(0 since the previous warning)") really does separate the interval argument from the count. And deleting the reset does make attempt 3 read as repeated, sleep 100 ms, and fail with the line quoted.
sessionSetupFailures is a runListen local now, and the comment above the pair names switchListenPort() starting the new thread before it stops the old. The reset comment names what it gives up. Both were asked for and both landed.
issue (blocking): When the peer aborts the handshake, the server logs "connected" and then goes silent for good.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:780
Session.close() publishes a StopMsg unconditionally — opendj-server-legacy/src/main/java/org/opends/server/replication/protocol/Session.java:84 sets protocolVersion = getCurrentVersion() and :190 gates only on localSessionError == null && protocolVersion >= V4. So any peer-side abort reaches us as a StopMsg: read before the peer's ReplServerStartMsg it lands on ReplicationServerHandler.java:175, read after it leaves waitAndProcessTopoFromRemoteRS() null and lands on :232. Both pass null, and abortStart(null) logs nothing (opendj-server-legacy/src/main/java/org/opends/server/replication/server/ServerHandler.java:218-225).
The pass then falls through to the unconditional report. A peer that rejects our handshake — its own duplicate-id check, a cross connect it resolves against us, a shutdown in progress — yields one 312, one 313 connected to replication server X for domain "o=test", and then nothing ever again: connect() returned true, so the peer is never blacklisted, and every later pass calls recordSuccess() on an already-cleared record, which returns false and logs nothing. Replication for that domain is dead and the log's last word is "connected".
The disclosed cost leans on "abortStart logs the duplicate id every second, unthrottled". That holds only for our-side aborts (ReplicationServerHandler.java:262, :267, non-null message). On the peer-side abort there is no line at all — and aPeerWhichStopsTheHandshakeStillClosesItsOutage pins that as intended.
The third abortStart(null) site, ReplicationServerHandler.java:191, is not affected: isAlreadyConnectedToRS returns true only when connectedRSs really holds a matching handler, so an inbound connection is up, 313 is true and clearing is correct.
A direction that avoids both discriminators already holed (the session, the registration): let the handshake tell its caller whether it aborted.
// ReplicationServerHandler.connect(...) -> false when it called abortStart()
if (!rsHandler.connect(baseDN, sslEncryption))
{
// the outage stays truthfully open, and runConnect() blacklists the peer for six passes
return false;
}
reportConnectionRestored(remoteServerAddress, baseDN);
return true;A V1 peer completes its handshake, so the V1 hole stays shut. Under multi-homing the abort is ours and carries a non-null message, which is logged.
todo (non-blocking): aPeerWhichAdvertisesAnotherAddressStillClosesItsOutage never reaches the mismatch it is named for.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerConnectFailureTest.java:192
connectedRSs' only writer is ReplicationServerDomain.register() (:2572), called from ReplicationServerHandler.java:242 only above V1 and only after a non-null waitAndProcessTopoFromRemoteRS() — which this peer prevents by leaving phase 2 unanswered. So isAlreadyConnectedToRS takes its oldRsHandler == null -> return false guard (opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServerDomain.java:1299-1304) and the address comparison at :1306 never executes. The advertised port is read on no executed path; the case would pass byte-for-byte with the real port advertised.
Measured: both mutants fail both new cases with identical assertion text, so this case kills nothing aPeerWhichStopsTheHandshakeStillClosesItsOutage does not. The multi-homing mechanism — round 2's blocker — stays unpinned. Either drop the case as redundant, or make it real: put a handler for PEER_RS_ID into connectedRSs under a different address URL before the outbound handshake, so isAlreadyConnectedToRS throws ERR_DUPLICATE_REPLICATION_SERVER_ID. Fixing the blocking item above will invert what both cases assert anyway.
todo (non-blocking): The sessionSetupFailures move is pinned by no test — restoring the field is a surviving mutant.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:360
runListen has three callers: ReplicationServerListenThread.java:60 and the two test invocations at opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerDynamicConfTest.java:585 and :741. Both run once on a freshly constructed server, where the field and the local start equally empty, so the first 311 warns under either form. The asymmetry the move fixes needs two overlapping runListen calls on one instance. Two sequential calls on one server discriminate it:
// same ReplicationServer instance, two listen passes, one unusable connection each
rs.runListen(firstFailingSocket);
rs.runListen(secondFailingSocket);
// instance-field form: the second warning is suppressed by the five-minute window
assertThat(countRecordsOf(records, "accepted a connection from")).isEqualTo(2);Not measured — the runner's three-run cap went to the connect() call site.
issue (non-blocking): Messages 312 and 313 still assert a connection the code no longer guarantees.
opendj-server-legacy/src/messages/org/opends/messages/replication.properties:641, :646
Both keys were authored under the !session.closeInitiated() guard and not revisited when it went: the file's diff over this delta is empty, and in BASE..HEAD both are pure additions. 312 says "This is reported once: the next message about this replication server comes when the connection is established"; 313 says "connected to replication server %s for domain "%s", which it had reported it could not connect to". The delta redefined the closing event to "the peer answered on its replication port".
On the silent sites above, 313 is the only line and it is false. On the logging sites the abort ERROR is emitted immediately before the 313, so the operator gets two adjacent contradictory lines, and anything keyed on msgID 313 reads the link as up. 312 itself nominates 313 as the completion event, so the contract is stated in the log, not only in the docs.
Mostly downstream of the blocking item: if 313 fires only for a completed handshake, both texts are true again. If the unconditional report stays deliberately, rewrite both to say what happened — "answered on its replication port", not "connected" — and check whether opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc repeats the old wording.
nitpick (non-blocking): The shared helper's javadoc states a safety property the code does not have.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerConnectFailureTest.java:228-229 — "The failure which opens each of the two windows blacklists the peer for six passes as well". blacklistedHosts is a Map local to runConnect() (ReplicationServer.java:595), written only at :636-639 from the connect thread's own connect(). The rs.connect(...) calls the test makes from the test thread blacklist nothing. The real protection is ConnectFailureReporter's idempotence in both directions, plus waitConnections() aligning the pass so the end-of-pass retainAll cannot erase the record — worth saying, since that is what makes the exact counts stable.
nitpick (non-blocking): A vacuous assertion.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerDynamicConfTest.java:142 — assertEquals(ReplicationServer.getAllInstances().size(), instancesBefore) cannot fail: allInstances.add(this) is the last statement of the constructor (ReplicationServer.java:278), after catch (ConfigException e) { abortInitialization(); throw e; } (:266-272), and abortInitialization() never touches allInstances. The sibling assertion on the changelog virtual-attribute rules is the one carrying the test. localPorts is added on the same post-catch line and asserted nowhere — that one could catch something:
assertFalse(ReplicationServer.isLocalReplicationServerPort(ports[1]));nitpick (non-blocking): The comment and the PR body name the wrong comparison.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServerDomain.java:1306 compares getServerAddressURL() with String.equals, not with HostPort.equals/normalizedHost; the HostPort path is used by getConnectedRSAddresses (ReplicationServer.java:678, ReplicationServerDomain.java:1002), not here. No reachable hole today — both sides are socket-derived numeric literals — but the reasoning quoted names a comparison this method does not perform.
…handshake as reachable, not as connected ReplicationServerHandler.connect() aborts a handshake rather than throwing, and two of its three aborts carry no message, which abortStart() logs nothing for. A peer which answers and rejects this server -- its own duplicate server id, a cross connect it resolves against us, a shutdown under way -- therefore left "connected to replication server" as the last thing said about a domain with no session for it. The handshake now tells connect() what it did, and the two things that used to be one are separated: the outage record is cleared whenever the peer answered on its replication port, so a peer this server never sees connected under the address it dialled -- a multi homed or NAT peer, a V1 peer -- still has its next real outage reported; and the message reports what happened, message 313 for a handshake which completed and the new message 314 for one which was aborted. The outcome also reaches runConnect(), which leaves a peer whose handshake aborts alone for a few passes rather than dialling it every second. Message 312 promised the next line would come when the connection is established, which is not what closes an outage any more, and the troubleshooting chapter said the same. Tests: the two peers which abort assert message 314 and the absence of 313, and the multi homing case registers a peer under another address through a full inbound handshake, so ERR_DUPLICATE_REPLICATION_SERVER_ID is really reached; a second outage reported after each of them is what the record being cleared looks like. Two passes of runListen() on one server pin that both throttles of the listen loop are confined to the listen thread.
|
Addressed in issue (blocking): a peer-side abort is reported as a connectionConfirmed link by link. I did not take What the two rounds ask for is two different things, so the fix does two things rather than picking one: handshakeCompleted = rsHandler.connect(baseDN, sslEncryption);
...
reportConnectionRestored(remoteServerAddress, baseDN, handshakeCompleted);
return handshakeCompleted;
The V1 peer completes its handshake, so it takes the 313 branch and stays out of this. issue (non-blocking): 312 and 313 assert a connection the code does not guaranteeFixed, and no longer downstream of anything: 313 is reported only for a handshake which completed, so its text is true as it stands. 312 promised "the next message about this replication server comes when the connection is established" and now promises the answer on the replication port which actually closes the outage. The troubleshooting chapter said the same and now describes both endings, the one with a session and the one without. todo (non-blocking):
|
| mutation | result |
|---|---|
the round-2 form: if (!session.closeInitiated()) around the report, return true |
killed: both abort tests, the second 312 never arrives |
| report every peer which answers as connected (313 for an abort) | killed: both abort tests, 314 never arrives |
sessionSetupFailures back in a field of the server |
killed: eachListenPassBoundsItsOwnFailures, 1 warning where 2 are due |
acceptFailures back in a field of the server |
killed: the same test, the same shape |
One thing seen and not chased: under the two killed mutations, where a test waits its full 30 s while the connect thread repeats the duplicate-id abort, the error log picks up severity=ERROR msgID=-1 msg=Index 0 out of bounds for length 0. It does not appear in any green run, and it is on the repeated-abort path rather than in anything this delta touches, so it looks like a defect of its own rather than something to fold in here.
Correction
The last paragraph above is wrong, and so was the test it was defending. Index 0 out of bounds for length 0 is not a defect of the repeated-abort path: it is the fake peer of aPeerRegisteredUnderAnotherAddressStillClosesItsOutage sending a TopologyMsg with no RSInfo, which waitAndProcessTopoFromRemoteRS() reads as rsInfos.get(0) above protocol version 4 (ReplicationServerHandler.java:460, "List should only contain RS info for sender"). The inbound handshake ended there, catch (Exception) in startFromRemoteRS turned it into abortStart(LocalizableMessage.raw(...)) -- which is where the msgID=-1 record comes from -- and register() was never reached.
So the outbound handshake which followed aborted on the unanswered second phase rather than on ERR_DUPLICATE_REPLICATION_SERVER_ID: the case pinned the path of aPeerWhichStopsTheHandshakeStillClosesItsOutage while claiming the multi-homing one. That is the finding of this round -- "never reaches the mismatch it is named for" -- reproduced in the replacement I wrote for it. The assertions passed either way, message 314 being reported for any abort.
Fixed in 06961e3d47: the peer sends its own RSInfo, and the registration is waited for and asserted -- waitForRegistrationUnder() reads getConnectedRSs() and checks both that the handler is there and that its address URL is the one which is not configured -- before the outbound handshake is offered.
Measured, -Dit.test=ReplicationServerConnectFailureTest each time:
| run | result |
|---|---|
| fixed | 3 cases pass, zero Index 0 out of bounds records |
the empty rsInfos put back |
fails on the precondition, "the peer should have registered with the domain", 4 such records in the log |
| the round-2 form | killed, both abort cases, the multi-homing one now on connect() returning true |
| every peer which answers reported connected | killed, both abort cases, 314 never arrives |
What let me miss it, and what I will not repeat: the error log records of these tests reach the build output only inside a failed assertion's text, so "absent from the green runs" was an artefact of the runs being green, not evidence about the server.
…er it says it registers registerPeerFrom() sent a TopologyMsg with no RSInfo, and waitAndProcessTopoFromRemoteRS() reads rsInfos.get(0) above protocol version 4: the inbound handshake ended on an IndexOutOfBoundsException, abortStart() logged it as a raw message, and register() was never reached. The outbound handshake which followed therefore aborted on the unanswered second phase rather than on ERR_DUPLICATE_REPLICATION_SERVER_ID, so the case asserted the path of the other test while claiming the multi-homing one -- the assertions pass either way, message 314 being reported for any abort. The peer now sends its own RSInfo, and the registration is waited for and asserted before the outbound handshake is offered: a handshake which ends any other way fails the case instead of quietly moving it onto another path.
maximthomas
left a comment
There was a problem hiding this comment.
praise: the round-3 blocker is closed, and closed with the right discriminator.
ReplicationServerHandler.connect() now returns the handshake outcome, so a peer that answers and
aborts no longer produces a lone false "connected". Measured on this head:
ReplicationServerConnectFailureTestpasses at06961e3d47, 3 cases, 0 failures.- Clearing the outage record whenever the peer answered at all is the right call, and it is pinned:
the mutant "log 314 but do not clear the record" is killed, 2 of 3 cases, both on
expected:<2> but was:<1>for the second 312. That mutant is in neither of your tables — your tests
are stronger than your own evidence shows. - Message 314 makes "reachable, no session" a state an operator can read, instead of hiding it under 313.
- Moving both
FailureLogThrottles andhandledAcceptFailureNanosfrom fields torunListen()locals
closes the listen-port-change silence and is what makes the new third caller safe —grepfinds no
FailureLogThrottlefield left in the class. chap-troubleshooting.adocno longer promises an established connection; it names 313 and 314 and
describes each.- The self-correction about the replacement test in your round-3 reply was right, and saved a round.
issue (blocking): after a 314 the recovery is never reported — the WARN stays the operator's last
word about a connected peer.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:815
Both branches sit under one guard, and recordSuccess() (:888) removes the baseDN before either runs:
if (connectFailures.recordSuccess(remoteServerAddress, baseDN)) // removes the baseDN
{
if (connected) { logger.info(NOTE_REPLICATION_SERVER_CONNECT_RESTORED, ...); } // 313
else { logger.warn(WARN_REPLICATION_SERVER_REACHABLE_NO_SESSION, ...); } // 314 — record now gone
}Peer restart is the ordinary path into this: port refused → 312; port open but the peer's domain is
not up yet, so it answers with a StopMsg → abortStart(null) → 314; seconds later the handshake
completes → recordSuccess() returns false → no 313. The only line on a completed handshake is
logger.debug(INFO_REPLICATION_SERVER_CONNECTION_TO_RS) (ReplicationServerHandler.java:261), which the
error log does not publish. Log-based alerting is left holding an ERROR and a WARN saying
"no change is replicated over this connection" over a connection that is replicating.
Not a regression of round 2's blocker: a later genuine outage still logs 312 (recordFailure at :742).
Fix — keep the clearing (the mutant above proves it is load-bearing), give ConnectFailureReporter a
last-reported state per peer instead of a present/absent record:
enum Reported { DOWN, REACHABLE_NO_SESSION, CONNECTED }
// 312 -> DOWN; abort -> WARN 314 only when the previous state was DOWN;
// completed handshake -> NOTE 313 whenever the previous state was DOWN or REACHABLE_NO_SESSION.That also stops a peer aborting every pass from emitting a 314 each time.
issue (blocking): 314's text does not match when 314 fires, in either direction. Round-3 finding 4
is not closed — it moved into the new message.
opendj-server-legacy/src/messages/org/opends/messages/replication.properties:648
314 is emitted for the raw handshakeCompleted == false, and ReplicationServerHandler.connect()
(:154-286) has 7 abortStart sites, all reaching it — null at :185, :201, :242; non-null at
:191, :273, :279 (the local ERR_DUPLICATE_REPLICATION_SERVER_ID), :285.
- The 4 non-null aborts log their reason on this server —
ServerHandler.java:224,logger.error(reason)— yet 314 says
"check the error log of the peer, where the reason it rejected the connection is logged". The reason
is already in the log being read. - 314 can only fire when a 312 record stands, and the sole
recordFailureis inside thecatchat
:742; an abort throws nothing. Two RSs that have been reachable since start-up and share a server id
therefore produce no 312 and no 314 at all — while 314's text is a standing topology diagnostic
("check that no two replication servers of the topology share a server id"). The code is
outage-scoped, the message is not.
Text, not control flow: gate the peer-log sentence on the null-reason aborts (pass the reason's presence
down instead of the bare boolean), or drop the topology sentence from a message that cannot fire in the
topology it names.
Also ReplicationServer.java:783: "two of the three aborts of ReplicationServerHandler.connect() pass
no message" — it is 3 of 7, and the 4 omitted are exactly the ones that make the text wrong.
issue (blocking): 312's rewritten text over-promises in a new direction.
opendj-server-legacy/src/messages/org/opends/messages/replication.properties:641 now says
"the next message about this replication server comes when it answers again on its replication port".
The already-connected branch clears the record and logs 313 for a connection the peer made inbound,
which connect() never dialled — as its own comment says:
// ReplicationServer.java:616-621
// Skip: already connected. The connection may be the one that peer made to
// this server, which connect() never sees, ...
reportConnectionRestored(rsAddress, domain.getBaseDN(), true);One-line edit, bundled here because the string is about to be released and translated.
issue (blocking): the replacement multi-homing case reaches the duplicate-id path but asserts nothing
that only that path produces.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerConnectFailureTest.java:288
The three assertions (one 314, zero 313, two 312) are string-for-string the sibling helper's, and 314 is
emitted for any handshakeCompleted == false. Remove the duplicate-id throw from
isAlreadyConnectedToRS and the handshake runs on to phase two, where the fake peer sends no
TopologyMsg → abortStart(null) at ReplicationServerHandler.java:232 → still one 314, zero 313,
two 312, all green. waitForRegistrationUnder asserts the setup, not that the outbound handshake
consumed it. Third appearance of this shape in this file.
One line closes it — the discriminator is clean, the StopMsg path logs nothing and the error-log capture
is server-wide:
assertThat(countRecordsOf(records, ERR_DUPLICATE_REPLICATION_SERVER_ID.get(...)))
.as("the outbound handshake reached the duplicate server id, not phase two")
.isEqualTo(1);suggestion (non-blocking): blacklistedHosts is keyed by host but armed by a per-domain handshake
outcome.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:632
if (blacklistedHosts.getOrDefault(rsAddress, 0L) > domainTicket) { continue; }
...
if (!connect(rsAddress, domain.getBaseDN())) { blacklistedHosts.put(rsAddress, domainTicket + 6); }domainTicket is constant within a pass, so on the pass the entry expires the first durably-aborting
domain re-arms it and every domain iterated after it is skipped again — permanently, not "a few
iterations". New in this delta: before it an aborted handshake returned true and blacklisted nothing.
Bounded in practice (RS↔RS dialling is bidirectional, and a duplicate server id aborts every domain
symmetrically), so: key by (host, baseDN), or state the permanence in the adoc, which currently
discloses only the cross-domain scope.
suggestion (non-blocking): the logSessionSetupFailure call site is pinned only at unit level.
eachListenPassBoundsItsOwnFailures (ReplicationServerDynamicConfTest.java:806) makes exactly one
session-setup failure per pass, so a mutant that builds a fresh FailureLogThrottle per failure passes
it unchanged. The acceptFailures call site is pinned — DCT:657 warnings == 1, DCT:659
suppressed == 2. FailureLogThrottleTest covers the class, not the wiring.
note (non-blocking): both mutation tables in the round-3 reply credit assertions that are never
evaluated.
Under "the round-2 form, return true" the earlier assertThat(rs.connect(...)).isFalse() fires first;
under "report every peer which answers as connected" the waitForErrorLogRecord for the 314 record spins
its timeout and ends at ReplicationTestCase.java:1018 fail(...). Either way "zero 313" and "two 312" are
never reached, so "both abort tests now assert three things" is true of what is written but unsupported
by the table offered. No code action — the measured mutant in the praise section settles the underlying
question in your favour; worth knowing so the tables are not cited later as proving more than they do.
note (non-blocking): the unthrottled ERR_DUPLICATE_REPLICATION_SERVER_ID flood a multi-homed peer
causes is pre-existing (present at base 92d88ca699) and is now tracked as
#1017. It is not charged to this PR — this
delta mitigates it roughly 7x by blacklisting the peer for six passes.
…ures Both conflicts were additions on both sides. The new messages of this branch (310-314) and the ones master added (319, 320) share no ordinal, so both blocks are kept; the import blocks of ReplicationTestCase are merged alphabetically.
…r it answered without one The reporter held whether an outage was open, so the message about a peer which answered and stopped the handshake consumed the record, and the handshake which completed seconds later found nothing left to close. A peer restarting takes that path: its port answers before its domains are up, so it is reported unreachable, then reported reachable with no session, and the session it goes on to establish was reported by nothing -- the only line on a completed handshake is a debug one the error log does not publish. The last word about a replicating connection was a warning saying no change was replicated over it. The record now holds the last state which was reported rather than the presence of an outage, so the session is a recovery from the answer without one and is reported as such. A genuine outage after it is still reported: a peer which stops answering has a state to leave as well.
…n promise, and pin the path each test names Message 314 sent the operator to the error log of the peer for a reason four of the seven aborts of ReplicationServerHandler.connect() log on this server, next to 314 itself, and it carried a standing topology diagnostic it cannot fire for: it is reported only where an outage was, and two replication servers which have been reachable since start-up and share a server id never open one. It now says which side logged the reason, and promises the session which follows rather than a topology check. Message 312 promised the next word would come when the peer answers on its replication port, where the connection the peer makes to this server closes the outage as well; 313 said the peer had been reported unreachable, which is not what was reported about one which answered without a session. The multi-homing case asserted one 314, no 313 and two 312, which an aborted handshake produces whichever way it aborted: it now asserts the duplicate server id its name is about, and fails with the throw removed. The listen test made one session setup failure per pass, which a throttle built for each failure reports as readily as one held for the pass; each pass now serves two connections, and the second is the one the throttle has to suppress. The troubleshooting chapter says the same, and says what the blacklist costs: a peer whose handshake does not complete is left alone for every domain, and the domain whose attempt failed is the one retried.
|
Addressed in 1b33496 and 100e683, on top of a merge with master (de7fd87) — #945 landed 319 and 320 in All four blocking items are fixed. The blacklist suggestion I took as documentation rather than as a rekey, with the reasoning below. issue (blocking): after a 314 the recovery is never reportedConfirmed, including the severity half: Taken as you wrote it. private enum Reported { DOWN, REACHABLE_NO_SESSION }
// recordFailure -> 312 unless the state is already DOWN
// recordReachableWithoutSession -> 314 only from DOWN
// recordConnected -> 313 from either, and drops the entry
One correction to the rationale rather than to the fix: "That also stops a peer aborting every pass from emitting a 314 each time" was already true before this change — the clearing form consumed the record on the first abort, so the second found nothing and returned Mutation, measured at
Four more cases pin the rest of the contract: the answer without a session is reported only out of an outage, only once, a peer which goes down after one is reported again, and issue (blocking): 314's text does not match when 314 firesConfirmed, and the count is yours: I took the second of your two options — drop the topology sentence — rather than plumbing the reason's presence down. Passing it down would let 314 name the side per abort, but it widens
The last clause is only true because of the item above. issue (blocking): 312's rewritten text over-promises in a new directionFixed. 312 now says the next message comes "when it can be reached again, whether it answers on its replication port or connects to this server itself", which is what the already-connected branch of issue (blocking): the multi-homing case asserts nothing only that path producesConfirmed and fixed. The three counts are string-for-string the sibling's because 314 is reported for any assertThat(countRecordsOf(records, ERR_DUPLICATE_REPLICATION_SERVER_ID.get(
servers[0].getMonitorInstanceName(), registeredAs, peerAddress, PEER_RS_ID).toString()))
.as("the outbound handshake should have aborted on the duplicate server id ...")
.isEqualTo(1);
suggestion (non-blocking):
|
| mutant | result |
|---|---|
a FailureLogThrottle built for each failure instead of one held per listen pass |
killed: expected [2] but found [4] warnings |
The accept() call site keeps the assertions it had.
note: the mutation tables credited assertions never evaluated
Taken, and it stands — under both of those mutants the earlier assertThat(rs.connect(...)).isFalse() or the waitForErrorLogRecord timeout ends the case before the counts are read, so "asserts three things" described the source rather than the run. The tables in the body are rewritten to name, for each mutant, the assertion which actually fails.
note: #1017
Noted, nothing charged here.
Verified
mvn -Pprecommit -pl opendj-server-legacy verify -Dit.test='ConnectFailureReporterTest,FailureLogThrottleTest,ReplSessionSecurityTest,ReplicationBrokerConnectFailureTest,ReplicationServerConnectFailureTest,ReplicationServerDynamicConfTest,ReplicationServerTest,TopologyViewTest,HandshakeAbortGenerationIdTest,ReplicationServerFailoverTest,ReplicationServerShutdownSyncTest,DSRSShutdownSyncTest' — 81 tests, no failures, on the branch merged with master at 5d176c6915. The shutdown classes are up from the earlier round because #945 and #948 added to them; running them is what covers this delta against the ServerState save they changed.
The three mutants above were applied together and reverted, each falling to a different class, so none of them masks another.
…d to a domain no session was restarted for restartService() leaves the session of a domain which owns it alone - it is shutting down, or disabled for the length of a total update - and the change was still reported as plain success. An administrator whose dsconfig named a replication server was told the domain runs on it while the session which negotiates that was never restarted, and a domain left disabled restarts none: enable() gives up when the data state it reads cannot be loaded, processImportEnd() calls it once, and nothing calls it again. restartService() is not the only restart which is suppressed. readAssuredConfig() and readFractionalConfig() do their own disableService()/enableService() pair under the same allowReconnection, so ReplicationDomain gets onSessionRestartSuppressed() - empty by default - and all three report through it. applyConfigurationChange() clears the flag before it applies anything and reads it after, both under serviceStateLock, and reports adminActionRequired with NOTE_REPLICATION_DOMAIN_SESSION_NOT_RESTARTED. Only on the success path: a change which could not be applied carries a reason of its own. A change of the "cn=external changelog" entry itself reports nothing of the kind. ConfigChangeResult.aggregate() copies the messages of a non-SUCCESS result only and never copies adminActionRequired, so the flag has one consumer, and it is the domain entry. Alongside: the test for serviceStateLock passed with the changeConfig(Set, Set) override deleted, because restartService() takes the same monitor at the end of the change. It now asserts that the ECL attributes are still unapplied while the caller holds the lock, which holds only when the whole of changeConfig() runs under it. Ordinals: 314 is claimed by OpenIdentityPlatform#935 as well, so the message moves to 326 and the new one takes 327.
maximthomas
left a comment
There was a problem hiding this comment.
The Reported enum is the right shape: holding the last state reported rather than whether an outage is open is what lets a 313 follow a 314, and dropping the entry in recordConnected keeps retainAll and the never-reported peer exactly as they were. Three more things landed well — the correction to your own rationale ("the clearing form already suppressed the repeated 314; the enum adds the 313 afterwards") instead of letting the claim stand; aPeerWhichAdvertisesAnotherAddressStillClosesItsOutage now asserting the whole ERR_DUPLICATE_REPLICATION_SERVER_ID built with the real arguments, which is the one thing only that path reaches; and the mutation tables rewritten to name the assertion that actually fails. eachListenPassBoundsItsOwnFailures serving two connections per pass is a real strengthening, and the seven-abort count is now right in the comment, in the message and in the body.
issue (blocking): the fix is pinned by no test — a one-line mutant at its call site survives all 28 cases
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:830
Restoring the pre-fix clearing semantics at the 314 call site, branch condition and log line untouched:
// ReplicationServer.java:830, the 314 branch, argument list unchanged:
- connectFailures.recordReachableWithoutSession(...)
+ connectFailures.recordConnected(...)survives — 28 cases, 0 failures (ConnectFailureReporterTest 13, ReplicationServerConnectFailureTest 3, ReplicationServerDynamicConfTest 12), measured at 100e683832 with your own invocation, 6:32 wall. That mutant is the blocking item this round was for: after a 314 the entry is gone and the handshake which completes seconds later logs no 313.
ConnectFailureReporterTest never constructs a ReplicationServer and never calls connect(), so its 13 cases pin the class, not the call site. The only integration coverage is the 3 cases of ReplicationServerConnectFailureTest, and none of them drives 312 -> 314 -> a completed handshake.
Two more mutants survive:
// ReplicationServer.java:793 — handshakeCompleted -> false: survives 28/28
// ConnectFailureReporter.recordConnected, made domain-blind: survives 13/13
return reported.remove(peer) != null;No unit case uses a second domain of the same peer. The consequence of the domain-blind form is not silence — recordFailure is keyed on the previous value, not on presence — but a repeated 312 plus a spurious 313 on every pass.
Fix: one integration case through connect() covering 312 -> 314 -> success, and one unit case with a second domain.
issue (blocking): 314's two sides do not cover three of the seven aborts
opendj-server-legacy/src/messages/org/opends/messages/replication.properties (message 314), mirrored at opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java:787 and in opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc:795.
Where this server rejected the peer, the reason is logged next to this message; where the peer stopped the handshake it logged nothing here, and the reason is in the error log of the peer
:273(IOException) and:285(Exception) are the peer going away, and the reason is logged here — so "in the error log of the peer" is false for them, and:787's "the remaining four are this server rejecting the peer" counts them on the wrong side.:201(isAlreadyConnectedToRS) is on neither side, and there 314 claims no session while a live inbound session replicates that domain.- The simultaneous-connection case the sentence names by hand is that same
:201shape, so the text is wrong about the one case it singles out.
Text only, but the ordinal is permanent once released. Restricting the peer-side promise to the two silent aborts (:185, :242) and fixing the count at :787 is enough.
issue (blocking): "the last message about a peer is what is true of it now" is not true
opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc:795
recordConnected drops the entry, so a session lost afterwards while the peer's listener still answers produces no 31x at all: connect() throws nothing, so no 312, and ServerReader logs the loss at information — logs/replication publishes it, logs/errors does not. The last word in the error log stays 313 "connected" while nothing is replicated. That is the silence this PR exists to remove, promoted to an invariant.
The same line still says two replication servers sharing a server id "is reported that way", which needs a standing 312 record — a limit you state in this round's reply while the chapter keeps the claim.
issue (blocking): 312 promises the inbound direction unconditionally
opendj-server-legacy/src/messages/org/opends/messages/replication.properties (message 312)
...whether it answers on its replication port or connects to this server itself
The inbound half closes an outage only through runConnect()'s already-connected branch, which needs a registered handler — registration happens above protocol V1 only — whose socket-derived address URL matches. A V1 peer and a multi-homed or NAT'd peer connect to this server and 313 never comes. Same permanent-ordinal cost as the item above; fix in the same pass.
issue (non-blocking): the new duplicate-id assertion races this server's connect thread
opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerConnectFailureTest.java:308
assertThat(countRecordsOf(records, ERR_DUPLICATE_REPLICATION_SERVER_ID.get(
servers[0].getMonitorInstanceName(), registeredAs, peerAddress, PEER_RS_ID).toString()))
.isEqualTo(1);waitConnections() rides one pass, it never stops the connect thread, and blacklistedHosts gives about 6.0-6.6 s of headroom against a 30 s REPORT_TIMEOUT_MS. A second outbound dial inside the window makes the count 2 and the case red. isGreaterThanOrEqualTo(1), or an upper bound on the wait, removes the race without weakening what the assertion proves.
suggestion (non-blocking): the chapter carries half of the blacklist trade-off, and the rekey question is still open
opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc:795
they are served by the connection the peer makes to this server
That holds for a peer which is up and dials back — not for one which is down, which is the very case you cite as the reason not to rekey. The line documents the per-domain cost and leaves the down-peer half of your reasoning in the reply only.
On the rekey itself: your cost argument is sound and this is your call. If you keep the documentation answer, say in the chapter that the skipped domains are covered only where the peer dials back.
…ithout one, and say where a reason is logged The state the previous round added is reported from ReplicationServer.connect(), and no case drove that call site: reporting the answer without a session through recordConnected() consumes the record, the handshake which completes seconds later reports nothing, and every case stays green. aSessionEstablishedAfterAnAnswerWithoutOneIsReported drives 312, 314 and the session which follows, on one socket, and asserts that no failure to reach the peer sits between the last two -- a session which closes a fresh outage is what the pre-fix form produces as well, so counts alone pin nothing. aConnectionForOneDomainLeavesTheOtherDomainsOfThePeerRecorded pins the domain key of recordConnected. Message 314 named a side per abort and had three of the seven on the wrong one: the two which are the peer going away have their reason logged here, and the cross connect this server resolves has it in neither log, the peer resolving one with the same silent abortStart(null). It now says where a reason was logged rather than which side ended the handshake, and denies a session to the attempt rather than to the domain. Message 312 no longer promises that an inbound connection closes an outage where this server cannot match it to the peer it dialled. The troubleshooting chapter drops "the last message about a peer is what is true of it now", which 313 dropping the record makes false, and names where a session lost later is logged instead. The javadoc of ReplicationServerHandler.connect() carried the same wrong abort count as the comment corrected last round.
|
Addressed in c98fa94. All four blocking items are fixed, and two of the findings do not hold as issue (blocking): the fix is pinned by no testConfirmed, all three mutants, and the first is the round-4 blocker itself: reporting the answer
Measured at c98fa94 with
The third stays unpinned on purpose, and it is worth saying why rather than leaving it out of the issue (blocking): 314's two sides do not cover three of the seven abortsConfirmed on all three counts, and the case you name by hand is worse than the finding says: the 314 no longer names a side. It says where a reason was logged: next to the message where this server issue (blocking): "the last message about a peer is what is true of it now"The invariant is gone from the chapter: 313 drops the entry, so an answer without a session after it The premise under it does not hold, though, and it decides whether this needs a third state. The shared server id half is fixed in the same sentence: the reason is logged where the handshake issue (blocking): 312 promises the inbound direction unconditionallyFixed: 312 now says the next message comes when the peer can be reached again, "either because this The V1 half does not hold: a V1 peer dialled from here completes the handshake -- phase two is issue (non-blocking): the new duplicate id assertion races this server's connect threadTaken: suggestion (non-blocking): the chapter carries half of the blacklist trade-offTaken as documentation, as last round: the chapter now says the skipped domains are served by the Verified
|
…never sees connected now costs The comment OpenIdentityPlatform#935 left in ReplicationServer.connect() justified closing an outage on the connection alone with the multi homed peer runConnect() could never match, and described that peer by what the old comparison did with it: registered under the source address of its session, never matched, its handshake aborted on a duplicate server id. Both addresses now identify it, so what is left of that reading is the peer which names an address this configuration does not use, and its handshake is resolved as a cross connect rather than reported as a duplicate. The last paragraph said the pass after a cross connect says what is true, which holds for the peer runConnect() can match and not for this one.
Fixes #911.
Three paths around the replication port gave up on a connection, or on a peer, without logging anything an administrator could act on. They are the complement of #906, which covered the inbound SSL handshake failure.
The accept loop
ReplicationServer:307caught every exception which is not a failed SSL handshake and dropped it with no logging at all, not even a trace, so it could not be diagnosed even with the debug log enabled. What reaches there is, in particular, theConfigExceptionof a trust store which cannot be read:TrustStoreBackend.loadKeyStore()opens the file again on everygetKeyManagers(),getTrustManagers()andcontainsKeyWithAlias()call, so anads-truststoredeleted, truncated or made unreadable after startup makes the server drop every inbound replication connection in silence. ASocketTimeoutExceptionfrom a peer which connects and then says nothing lands there too, being noSSLException.The failure of
accept()itself is now separated from the failure to build a session, because it is a different problem: the listen socket stays open across it, so the loop came straight back toaccept()and, on a process out of file descriptors, span on it at full CPU without a line in any log. The thread now waits 100 ms before accepting again, but only when the failure repeats within that window, so that a connection reset between the handshake andaccept()costs the connections behind it nothing.Two things decide what "repeats" means, and both matter:
accept()puts the clock back a whole interval. A loop which is serving connections is doing work rather than spinning, and without the reset a stream of connections aborted beforeaccept()— a health check, a port scan — would charge the listen port a wait per probe, and the peers queued behind them would pay it. What that gives up is the failure which alternates with a connection: a process which frees a file descriptor now and then has the accept it lets through reset the clock, and the failure behind it is timed as isolated, so the loop turns as fast as the connections arrive. The warning is throttled either way, so the error log holds one line per five minutes of it on both sides of that trade.Both are logged through
FailureLogThrottle, which is the throttle #906 introduced for the handshake warning, extracted unchanged;ReplSessionSecuritynow delegates to it and its test is untouched. Both throttles — the one ofaccept()and the one of the session which cannot be started on an accepted connection — arerunListenlocals, alongside the backoff clock and for the same reason:switchListenPort()starts the new listen thread before it stops the old one, and a five minute window opened on the port which was left would otherwise suppress the first failure on the port which replaced it.The outgoing RS to RS connect
ReplicationServer:490only traced the failure, so a replication server whose outgoing connection failed logged nothing inlogs/errors: the problem was visible solely in the log of the peer, which is the machine whose configuration is right. Success was no more visible,INFO_REPLICATION_SERVER_CONNECTION_TO_RSbeing written at debug level.The connect thread retries a failed peer every few seconds for as long as it is down, and a peer being down is a normal state, so
ConnectFailureReporterreports it once per outage and per (peer, domain), and reports the connection which ends the outage as well. Three shapes of that bookkeeping needed care, and all three are covered byConnectFailureReporterTest:connect()never sees; the already-connected branch ofrunConnect()clears the record, otherwise the next outage of that peer would be silenced;reportConnectionRestored(), so an outage cannot be closed in the record without being closed in the log — which is how it would be reported open and never reported closed;retainAllforgets those on every pass.What the outage is decides what closes it, and what the handshake did decides what is reported for it.
WARN_REPLICATION_SERVER_CONNECT_ERRORis reported for the socket and for the session built on it —ReplicationServerHandler.connect()throws nothing of its own, aborting a handshake it cannot complete by closing the session and returning — so an attempt which reaches the end ofconnect()is one whose peer answered on its replication port, and that is the outage ending. The outage is closed whatever the handshake did next, because holding it open for a peer which answers reports that peer unreachable while it is answering, and silences its next real outage. What the record holds is not whether an outage is open but what was last reported about the peer, and that is what leaves the session a peer establishes after it answered without one still reportable: a record which is merely present or absent is consumed by the message about the answer, and the handshake which completes seconds later finds nothing left to close. A peer restarting takes exactly that path -- its port answers before its domains are up.Every narrower reading holes on a peer whose connection this server does not see under the address it dialled, and there is one for each of them:
ReplicationServerHandler.connect()registers only above V1 — theFIXMEthere is older than this — so such a peer is connected and never registered;ServerHandler.toServerAddressURL()taking the host fromsession.getRemoteAddress(), so the already-connected branch ofrunConnect()compares the configured address against one it never matches — and the handshake this server offers that same peer aborts onERR_DUPLICATE_REPLICATION_SERVER_ID,abortStartclosing the session, so an open session is never seen at the end ofconnect()again.A record left uncleared is not a line too few but a peer gone silent:
recordFailurereturnsfalsefrom then on, so the next real outage of that peer is not reported at all.The handshake is not left to report itself, because it cannot:
ReplicationServerHandler.connect()aborts at seven places and three of them pass no message,abortStartlogging nothing without one — aStopMsgread where the peer'sReplServerStartMsgwas due, a cross connect this server resolves against a peer it is already connected to, and a phase two the peer leaves unanswered.Session.close()publishes aStopMsgfor every abort a peer makes, so a peer which stops the handshake — a shutdown under way, a cross connect it resolves against us — reaches us as one of those silent aborts. Reporting the recovery as a connection would leave "connected to replication server" as the last thing said about a domain which has no session for it. The other four have their reason logged here byabortStart, and they are not all of one kind: this server rejecting the peer, its own duplicate server id check included; the peer going away while the handshake ran; and whatever else fails on this side of it.So
ReplicationServerHandler.connect()now returns whether the handshake completed, andconnect()reports message 313 for a peer it is connected to and the new message 314 for one which answered and stopped the handshake — the latter saying where a reason was logged rather than naming a side: next to 314 itself where this server ended the handshake, and nothing there where the peer ended it. A side is not what it can name. Two of the four aborts which carry a reason are the peer going away rather than a rejection, and the abort which carries none may have been logged nowhere at all: the peer resolves a cross connect with the same silentabortStart(null), one line intostartFromRemoteRS(). The one of the three silent aborts where a session for the domain does exist is the cross connect this server resolves, and 314 denies a session to the attempt rather than to the domain: that session is the connection the peer made, and the already-connected branch reports it on the next pass. It promises the session which follows instead of a standing topology check it cannot fire for: 314 is reported only where an outage was, so two replication servers which have been reachable since start-up and share a server id never reach it. The same outcome reachesrunConnect(), which leaves a peer whose handshake aborts alone for a few passes rather than dialling it every second: the reason such a peer logs on its own side is logged about six times less often as well.Message 312 promised that "the next message about this replication server comes when the connection is established", which is not what closes an outage; it now promises the peer being reachable again, either because this server reached it or because it connected to this server from the address it is configured under — the already-connected branch of
runConnect()closes an outage for a connectionconnect()never dialled, and matches such a connection to the peer by the socket-derived address URL its handler is registered under, which is why the promise is not made for every inbound connection — and the troubleshooting chapter describes both endings.The data server side
WARN_COULD_NOT_FIND_CHANGELOGandWARN_NO_AVAILABLE_CHANGELOGSname no cause, but the two are not equally blind. The cause is built for every replication server contacted and was logged only for the elected one, and none is ever elected when none of them answers: a rejected certificate, a refused connection and a wrong port then all read as "unable to connect to any replication servers". Every server contacted now reports its own cause, next to the summary which names none of them, reusingWARN_NO_CHANGELOG_SERVER_LISTENING,WARN_TIMEOUT_CONNECTING_TO_RSandWARN_EXCEPTION_STARTING_SESSION_PHASEas they stand.connectionErrorbounds the volume: it is set as soon as an attempt reaches no server at all and stays set until a session is established, so the 500 ms loop which retries a total outage reports its first pass only. It is not set while the broker is connected, so the unreachable servers of a topology which still serves the broker are reported again on each reconnection — one line each, so a reconnection costs as many lines as there are servers it could not reach, where it used to cost none. A broker reconnects when its session is lost rather than on a schedule, and a server unreachable across several reconnections is one whose configuration or certificate needs looking at.The severity says what the failure cost the broker rather than what the message is named: the elected server keeps the error it was reported with, a server which was only contacted is a warning.
WARN_EXCEPTION_STARTING_SESSION_PHASEcarries the whole stack trace for the elected server, as it did before this PR, and the message alone for the others — that branch is not throttled, anSSLExceptionis not paced by a connect timeout the way a refused connection is, andcollectReplicationServersInfo()reruns over every URL on each reconnection.Where the suppressed records go
A failure the throttle keeps out of the warnings is still recorded, with the
informationseverity. That severity is not invisible:cn=Replication Repair Loggerships enabled withds-cfg-log-file: logs/replicationandds-cfg-override-severity: SYNC=INFO,ERROR,WARNING,NOTICE,LoggingCategoryNamesmapsorg.opends.messages.replicationtoSYNC, andTextErrorLogPublisher.isEnabledForprefers the override. So the throttle bounds whatlogs/errorsholds, whilelogs/replicationholds one record per failure.Messages 105, 310 and 311 say so, and so do the sample quoting 105 and the troubleshooting chapter, whose instruction for reaching those records in the error log as well names
info— the token thedefault-severityenumeration accepts — rather thaninformation, which it rejects. Message 105 and its sample belong to #906; this PR had already re-worded them, and the corrected paragraph sits three lines under the sample, so leaving them would have shipped a contradiction on one page.Two things found while there
A session which failed after its handshake leaked. The outer
catchofrunListenlogged and looped without closing the session, so a peer killed after the handshake, or one which stopped answering past the connection timeout, cost one socket and one file descriptor for the life of the process. Closing it there is safe:startFromRemoteDS,startFromRemoteRSandconnecteach catch everything andabortStart, which closes the session, so a session reaching that catch is owned by nothing else.logger.debugof a localized message does not go to the debug log.OpenDJLoggerAdapterpublishes it to the error log with theinformationseverity, which is what the section above is about.Message ordinals
The four new messages were 307 to 310 and are now 310 to 313: #892 landed 307, 308 and 309 in
replication.propertieswhile this branch was open. No Java change was needed, the generated constants dropping the ordinal suffix. Message 314 was added in the third review round. #945 landed 319 and 320 while this branch was open as well; the merge with master put them beside 310 to 314 rather than over them.replication.propertiesholds no duplicate ordinal: the highest this branch adds is 314, and the highest in the file is 320.Verified locally, on the branch merged with master
mvn -Pprecommit -pl opendj-server-legacy verify -Dit.test='ConnectFailureReporterTest,FailureLogThrottleTest,ReplSessionSecurityTest,ReplicationBrokerConnectFailureTest,ReplicationServerConnectFailureTest,ReplicationServerDynamicConfTest,ReplicationServerTest,TopologyViewTest,HandshakeAbortGenerationIdTest,ReplicationServerFailoverTest,ReplicationServerShutdownSyncTest,DSRSShutdownSyncTest'— 81 tests, no failures, on the branch merged with master at 5d176c6. The last classes cover the interaction with [#900] Time the ReplicaOfflineMsg grace period per replica, and spend it where the message can still be forwarded #919, [#889] Keep a change the replay could not apply out of the ServerState #892, [#908] Wait for the changes being applied before a domain going down saves its ServerState #945 and [#916] Keep an update that lands during a ServerState save out of the saved flag #948, which changedshutdown(), the ServerState save andReplicationTestCase.mvn -Pprecommit -pl opendj-server-legacy verify -Dit.test='ConnectFailureReporterTest,ReplicationServerConnectFailureTest,ReplicationServerDynamicConfTest,ReplicationBrokerConnectFailureTest,FailureLogThrottleTest,ReplSessionSecurityTest'— 36 tests, no failures, at c98fa94, which is the round-5 delta: the classes it changes and the ones which read the messages it rewords. The run above is what covers the rest.HandshakeAbortRegistrationTest(3) andGroupIdHandshakeTest(2) on their own: in a long run they collide on the administration connector port, which is the harness rather than this change.IndexOutOfBoundsExceptionofrsInfos.get(0)in the log, where before it passed on the wrong path.if (!session.closeInitiated())around the report,return true) and reporting every peer which answers as connected each fail both abort tests, and putting either throttle of the listen loop back in a field of the server failseachListenPassBoundsItsOwnFailureswith one warning where two are due. From this one, the three applied together because each falls to a different class: the present-or-absent record —recordReachableWithoutSessionconsuming the entry the wayrecordSuccessdid — failsaSessionEstablishedAfterAnAnswerWithoutOneIsReported; removing theERR_DUPLICATE_REPLICATION_SERVER_IDthrow fromisAlreadyConnectedToRSfailsaPeerRegisteredUnderAnotherAddressStillClosesItsOutagewithexpected:<1> but was:<0>while its other three assertions stay green, which is the finding that case was given; and building aFailureLogThrottlefor each failure rather than holding one per listen pass failseachListenPassBoundsItsOwnFailureswith four warnings where two are due. From this round, the two applied together because they fall to different classes: reporting the answer without a session throughrecordConnected()at the call site of 314 — the pre-fix clearing, with the branch and the log line untouched — failsaSessionEstablishedAfterAnAnswerWithoutOneIsReportedon a 313 which never arrives, the run holding the 312, the 314 and thenINFO_REPLICATION_SERVER_CONNECTION_TO_RSfor a session which is up; and a domain-blindrecordConnected,reported.remove(peer) != null, failsaConnectionForOneDomainLeavesTheOtherDomainsOfThePeerRecordedwithexpected:<false> but was:<true>.What the tests pin, and what fails without the code under them:
ReplicationServerConnectFailureTestdrives the reporting throughReplicationServerrather than through the bookkeeping alone. Two of its tests drive a peer the already-connected branch ofrunConnect()can report nothing about, so thatconnect()is the only place a recovery can come from.aPeerWhichStopsTheHandshakeStillClosesItsOutagehas it answer theReplServerStartMsgwith aStopMsg;aPeerRegisteredUnderAnotherAddressStillClosesItsOutagehas it complete a full inbound handshake first, registering under an address it is not configured under, so that the outbound handshake really reachesERR_DUPLICATE_REPLICATION_SERVER_ID— the multi-homing mechanism rather than a stand-in for it. That registration is a precondition of the case rather than an assumption: the test readsgetConnectedRSs()and fails unless the handler is there under the address which is not the configured one, because a handshake which ends any other way is an abort too, and message 314 is reported for every abort — the case would otherwise pass while pinning the path of the test next door. Both assert message 314, the absence of 313, and a second outage reported afterwards, which is only reachable because the first was closed: they fail if the recovery is gated on the session left open, on the registration or on the address, and they fail if an aborted handshake is reported as a connection. Those three counts are what an aborted handshake produces whichever way it aborted, so the multi-homing case asserts theERR_DUPLICATE_REPLICATION_SERVER_IDits name is about as well, which only the registration under another address URL reaches.aPeerWhichIsDownIsReportedOnceAndItsReturnIsReportedruns two real replication servers with their own connect threads, so it coversrunConnect()and pins that messages 312 and 313 are emitted at all.aSessionEstablishedAfterAnAnswerWithoutOneIsReportedis the peer restarting: down, then answering and stopping every handshake, then completing one, all on the socket it answers on. It pins the call site of 314 rather than the bookkeeping — reporting the answer throughrecordConnected()consumes the record and passes every test ofConnectFailureReporter— and it asserts where the 314 and the 313 sit in the error log rather than only how many there are: a failure to reach the peer between them would open an outage of its own, and a 313 which closes a fresh outage is what the pre-fix form produces as well.logThrottledFailure's interval and count arguments are swapped. The second of them serves a connection no session can be started on, which is also what pins message 311 and the order of its arguments;eachListenPassBoundsItsOwnFailuresruns two passes ofrunListen()on one server, each failing once ataccept()and serving two connections no session can be started on, and fails if either throttle is a field of the server rather than a local of the listen thread — and, the second connection of a pass being the one its throttle has to suppress, if a throttle is built for each failure instead;ReplicationBrokerConnectFailureTestasserts the severity of a cause reported for a server which was only contacted, not only its text;ConnectFailureReporter, including whatretainAllforgets.Not pinned, and left so knowingly: the call site of
reportConnectionRestoredinsiderunConnect()as opposed to the method itself —aPeerWhichIsDownIsReportedOnceAndItsReturnIsReportedreports the recovery from whichever of the two call sites wins the race, and the two which pin the one inconnect()drive a peer the other cannot see. Nor is the argumentconnect()passes: reporting every completed handshake as an answer without a session survives all four cases, because the 313 then arrives one pass later from the already-connected branch, which passes the literaltrue, and the counts of any case whose peer registers are the same either way. Killing that one needs a peer which completes an outbound handshake and registers nothing, which is the V1 shape —ReplicationServerHandler.connect()registers only above V1 — and what it would buy is a warning the next pass corrects.Every test configures the peer it drives and creates the domain before anything is recorded, and the ones which record from the test thread wait a whole pass of the connect thread first:
runConnect()snapshots the domains at the top of a pass and runsretainAllagainst that snapshot at the bottom, so a pass which started before the domain existed ends by clearing the record.Left out on purpose
runConnect()incrementsdomainTicketonce per pass while the blacklist is keyed by address alone, so the first domain to fail for a peer re-blacklists it before the others are reached, and the same domain wins every pass. Message 312 and the troubleshooting chapter now say the domain named is the one the attempt was for rather than the only one affected. Keying the reporter by peer alone would report it honestly but regresses the mixed case — a peer reachable for one domain and failing for another would alternate 312 and 313 every time the blacklist expires — so real per-domain reporting wants the blacklist keyed by(address, baseDN), in its own issue. A handshake which does not complete now blacklists the peer as a failure to connect does, which it did not before this delta, so the same degeneracy covers a peer which aborts durably: the domain whose attempt aborted is the one retried, and the other domains of that peer are served by the connection it makes to this server, replication servers dialling each other both ways. The troubleshooting chapter says so.