[#963] Read the changelog again for a following replica the domain is ahead of - #964
Conversation
|
Ordinal moved: Six open branches had each read 310 as the first ordinal free in master and taken it - #935, #945, Nothing catches this on the way in. The additions land in different parts of the file, so git merges The open PRs which add to the file now hold 310-325 with nothing claimed twice:
No Java moved with it: the generated constant is the key name without its ordinal, so the rename is |
ef79edc to
58259b7
Compare
|
Rebased onto master at 5d176c6 and force-pushed (58259b7) - the PR is mergeable again. The conflict was confined to the tail of @maximthomas the description has also been brought in line with what the evidence says now, because
Re-requesting your review on that basis. The two things worth your eye are the guard - whether |
maximthomas
left a comment
There was a problem hiding this comment.
praise: The regression is real and the test proves it — aFollowingReplicaIsSentAChangeItsQueueNeverReceived fails at master (Expecting actual not to be null, 10.4 s) and passes here (1.4 s). The check sits in the idle branch of the wait loop, so the delivery path pays nothing, and if (msgQueue.isEmpty()) continue; reuses the existing catch-up reader instead of adding a second one. The WARN prints both states, which is exactly what an operator needs to name the lagging replica. DataServerHandler.isFedByTheDomain() mirrors put()'s BAD_GEN_ID / FULL_UPDATE filter and has its own guard case. The rebase is clean: every Java line is identical to the pre-rebase head, only the message ordinal moved.
issue (blocking): In a mesh of three or more replication servers this check fires in steady state on every peer-RS handler — a WARN, a cursor open and an RS→RS re-send after every change relayed by a third RS.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServerHandler.java:535-538
put() relays to connectedRSs only inside if (sourceHandler.isDataServer()) (ReplicationServerDomain.java:360). A peer-RS handler's serverState is written only at the handshake, by what this RS sends it, and by what it sends this RS. So on RS1 the handler for RS2 never learns a change DS3 wrote through RS3, while RS1's domain state has it. After 0.5–1 s idle: following = false, WARN, cursor, and the change is re-sent to RS2, which already holds it. The throttle never engages because every new change advances the domain state — (N−1)(N−2) WARNs and re-sends per change. On the receiving RS LogFile.append drops the out-of-order record silently, but publishUpdateMsg still returns true and notifyCookieEntryAdded fires, so every cookie-mode persistent search gets a duplicate entry. This is a regression: at master diffChanges is never consulted for a following handler. The green suites listed in the description assert on the origin RS only, which has no gap.
The invariant "a following handler with an empty queue has everything the domain has" holds only for handlers put() feeds everything — DS handlers. Exclude RS peers:
@Override
boolean isFedByTheDomain()
{
// put() hands a peer RS only the changes of the DSs connected to this RS: what a third RS
// relayed never reaches this handler's queue nor its state, so the domain is always "ahead".
return false;
}If the RS→RS loss must be covered as well, diff only the serverIds of replicationServerDomain.getConnectedDSs() — never the whole domain state. Either way, add a 3-RS case: a DS write behind RS3, ≥1.5 s idle, then assert following is still true on RS1's handler for RS2 and no WARN was logged.
issue (non-blocking): When case 1 fails or times out, the receiver thread spins at 100 % CPU for the rest of the failsafe JVM.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/MissedUpdateRecoveryTest.java:181-196
nextUpdate() loops on broker.receive() and catches only SocketTimeoutException. The finally calls stop(broker) first; after that ReplicationBroker.receive() returns null immediately (while (!shutdown) … return null), nothing in the loop observes the interrupt from shutdownNow(), and the executor is non-daemon. The run the description advertises — red on master — leaves a core-burning thread for every later class in the fork.
final ReplicationMsg msg = broker.receive();
if (msg == null || Thread.currentThread().isInterrupted())
{
return null; // the broker was stopped
}
if (msg instanceof UpdateMsg)
{
return (UpdateMsg) msg;
}issue (non-blocking): The throttled return leaves changesLookedMissing armed, so in a persistent-gap state the next re-read fires on the first wait after the domain advances — inside the publish→add window the comment above says is protected.
opendj-server-legacy/src/main/java/org/opends/server/replication/server/MessageHandler.java:475-480
Sequence: a re-read finds nothing → following = true → the next wakeup arms the flag → throttled returns keep it armed → the domain advances (publishUpdateMsg runs before addUpdate) → the very next check fires. Result: a spurious WARN naming an in-flight change plus a cursor open; no loss. The two-wait debounce is a one-wait one exactly where it matters.
if (lastMissingChangesDomainState != null
&& ServerState.diffChanges(domainState, lastMissingChangesDomainState) <= 0)
{
// re-arm: the next advance of the domain must again be seen over two waits
changesLookedMissing = false;
return;
}suggestion (non-blocking): Of the five mechanisms the description lists, the test pins one — the delivery. The two-wait guard, the once-per-advance throttle, the WARN, the FULL_UPDATE branch and the RS override all survive deletion with both cases green.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/MissedUpdateRecoveryTest.java:95-98
Case 1 asserts isNotNull + CSN; case 2 asserts BAD_GEN_ID and !cover(csn) — and case 2 is green at master too, so it pins the guard only against a HEAD-without-guard mutant. Both hold the domain state still after one publish. The argument "the WARN did not appear in the CI run, so the candidate is ruled out" rests on a line no test asserts. Cases worth adding:
- (a) domain ahead for one wait only → no re-read,
followingstaystrue; - (b) a second miss with an unchanged domain state → no second cursor;
- (c) the WARN is logged exactly once and names both states;
- (d) a
FULL_UPDATEreplica is left alone (mirror of case 2); - (e) three RSs: the peer handler is left alone (after the blocking fix above);
- (f) a change delivered through
put()keepsfollowingtrueand logs nothing.
nitpick: The comment names the wrong source of the generation id.
opendj-server-legacy/src/test/java/org/opends/server/replication/server/MissedUpdateRecoveryTest.java:127
The domain takes its generation id at the first DS handshake (ServerHandler.setDomainGenerationIdOnStart()), not from the first change; put()'s setGenerationIdIfUnset() is a no-op by then. The publish is still needed, for another reason:
// a change the domain holds and must not hand to the bad-generation-id replica opened belowissue (non-blocking): diffChanges can overflow to a negative sum, and the new check then reads "not behind".
opendj-server-legacy/src/main/java/org/opends/server/replication/common/ServerState.java:385
Pre-existing, now load-bearing: the sum is an int, and CSN.diffSeqNum returns Integer.MAX_VALUE - (seqnum2 - seqnum1) + 1 on a seqnum reset (CSN.java:380). Two replicas whose seqnum wrapped overflow the sum negative. Either accumulate in a long and clamp, or skip the arithmetic here and ask per serverId whether the domain CSN isNewerThan the handler's:
for (Map.Entry<Integer, CSN> entry : domainState.getServerIdToCSNMap().entrySet())
{
final CSN handlerCSN = serverState.getCSN(entry.getKey());
if (handlerCSN == null || entry.getValue().isNewerThan(handlerCSN))
{
return true; // behind
}
}
return false;question (non-blocking): Can the re-read hand a following DS a ReplicaOfflineMsg?
opendj-server-legacy/src/main/java/org/opends/server/replication/server/MessageHandler.java:511-517
fillLateQueue() opens getCursorFrom(serverState) with no per-handler filter, and a ReplicaCursor can yield a ReplicaOfflineMsg, which put() never queues for a DS. That is pre-existing on the catch-up path, but this PR makes that path re-enterable in steady state for a following DS. Has the DS side of a ReplicaOfflineMsg arriving that way been checked?
question (non-blocking): Is the catch-up re-send after a BAD_GEN_ID → NORMAL transition intended?
opendj-server-legacy/src/main/java/org/opends/server/replication/server/DataServerHandler.java:292-296
put() does not queue for a BAD_GEN_ID DS (ReplicationServerDomain.isUpdateMsgFiltered), so its serverState falls behind the changelog while it is refused. Once the status returns to NORMAL, the first idle second re-reads and sends everything it missed — which master never did. Does resetGenerationId clear the changelog before the status flips back?
|
Round 2 is on the branch as a635266. Point by point: Peer-RS handlers (blocking) - confirmed, and reproduced before it was fixed: Receiver thread - replaced by a Armed flag after the throttled return - confirmed; the one-line re-arm halves it rather than Coverage - all six are in Test comment - taken as suggested.
BAD_GEN_ID -> NORMAL - that transition does not exist: The description is brought in line with the code. |
…eplica the domain is ahead of A handler which is following is served by MessageHandler.add() alone: the domain hands it every change it receives, so an empty message queue means the consumer has everything. fillLateQueue() is the only reader of the changelog and is not called again while the handler follows, so a change which reached the changelog without reaching that queue was never sent again, and the replication server considered the replica up to date for the rest of the session. ReSyncTest.testResyncAfterRestore failed that way: the replica reconnected after a restore announcing a state behind the entry added in between, and nothing came. While waiting on an empty queue the handler now compares its state with the state of the domain and goes back to the catch-up path when it is behind, which reads the changelog again and delivers what is missing. The comparison is the in-memory one getRcvMsgQueueSize() already makes, and it must hold over two waits so that a change simply on its way from publishUpdateMsg() to addUpdate() is not taken for a missing one. The changelog is read again once per advance of the state of the domain, so a miss which repeats does not spin. Handlers the domain filters out are left alone: the state of a replica with a bad generation id, of one being initialized, and of a replication server whose generation id does not match is legitimately behind, and reading the changelog on their behalf would move their state past changes the writer then drops.
…nothing else claims
…state of the domain one wait back A peer replication server is handed nothing but the changes of the directory servers connected to this one: what a third replication server relayed never reaches its queue nor its state, so the domain is always ahead of its handler and the check fired on every relayed change in a mesh of three or more, sending the peer what it already held. isFedByTheDomain() now defaults to false and DataServerHandler carries the only override; the ReplicationServerHandler override and the isDifferentGenerationId visibility change go with it. The handler is compared with the state of the domain seen at the previous wait rather than counting the waits which saw the domain ahead: what the domain received since the previous wait may be on its way, whatever gap the changelog was already read for, and a flag armed by such a gap fired on the first tick after any advance. The comparison is ServerState.cover(), per replica and without arithmetic: diffChanges() sums CSN.diffSeqNum(), which returns about Integer.MAX_VALUE for a replica whose seqnum went back with its time forward - a restart from a lagging ds-sync-state - and two more changes overflow it. MissedUpdateRecoveryTest: the receiver leaves when the broker is stopped instead of spinning; the warning is checked once and for both states; a change on its way, the ordinary path, the throttle, a change on its way next to a throttled gap, a replica in full update and a three-RS mesh are pinned.
a635266 to
95ea7fb
Compare
|
Rebased onto master at 13d57e0 and force-pushed (95ea7fb) - the PR is mergeable again. The conflict was the same place as last time, the tail of |
maximthomas
left a comment
There was a problem hiding this comment.
praise: The rebase onto master is clean: the three production Java files are byte-identical to the approved head a635266, and CI on 95ea7fb is green in all five ubuntu failsafe cells. stopFollowingWhenChangesAreMissing() (opendj-server-legacy/src/main/java/org/opends/server/replication/server/MessageHandler.java:464-488) now compares against the domain state captured at the previous wait, which closes the round-1 publish->add false positive by construction, and the once-per-advance throttle is pinned by execution: deleting it turns aGapAlreadyReadForIsNotReadAgainUntilTheDomainAdvances (:359) and aChangeOnItsWayIsNotReportedMissingNextToAGapAlreadyReadFor (:431) red. The eight cases in MissedUpdateRecoveryTest read as a spec of the mechanism, and the publishThenQueueLate javadoc says exactly what the hold is for.
issue (non-blocking): The previous-wait compare is the mechanism that replaced the round-1 finding, but no case pins it deterministically. I ran the mutant that compares against the current domain state instead:
// MessageHandler.java:471, mutant
final ServerState missingSince =
domainStateAtPreviousWait == null ? null : replicationServerDomain.getLatestServerState();Result at 95ea7fb: 8 ran, 1 failed. aChangeOnItsWayToTheQueueIsNotReadAgain stays green. The hold in publishThenQueueLate (opendj-server-legacy/src/test/java/org/opends/server/replication/server/MissedUpdateRecoveryTest.java:522-528) is 400 ms, and the previous handler.add() notify re-phases the 500 ms tick, so the hold never straddles a tick and the check never runs while the change is on its way:
publishToChangelogOnly(replicationServer, baseDN, msg);
Thread.sleep(ON_ITS_WAY_MS); // 400 ms, tick is 500 ms and was re-phased by the last add()
handler.add(msg);The mutant dies only in aChangeOnItsWayIsNotReportedMissingNextToAGapAlreadyReadFor at :431, and only because Thread.sleep(2500) at :418 races the fifth tick; one sample, killed in round 1 of 5. The same phase lock works the other way too: a sleep(400) overshoot of more than 100 ms at the wrong phase puts two ticks inside one hold and reds :266 or :431.
Suggested fix, in the test only: make the hold straddle a tick by construction instead of by wall clock. Either observe the handler returning from a wait with the change published but not yet queued (a CountDownLatch hooked where stopFollowingWhenChangesAreMissing() returns, released under test), or hold for longer than one tick and assert no WARN was logged across it:
publishToChangelogOnly(replicationServer, baseDN, msg);
awaitOneCheckTick(handler); // returns after the check has run at least once
handler.add(msg);
assertThat(warningsFor(csn)).isEmpty();Then run the current-state mutant above and confirm every case that holds a change on its way goes red.
… a wait has seen it The tests which hold a change on its way held it for 400 ms by wall clock, and the check never ran while they did: a delivery from the queue re-phases the 500 ms wait, so the tick always landed after the hand-over. A mutant comparing with the current state of the domain instead of the state seen at the previous wait survived aChangeOnItsWayToTheQueueIsNotReadAgain and died in aChangeOnItsWayIsNotReportedMissingNextToAGapAlreadyReadFor only by the race of the fifth tick with the 2.5 s watch - the same race an overshoot of that sleep turns against the real code. Found in review. MessageHandler exposes the state of the domain seen at the previous wait, package private, and publishThenQueueLate() waits for a tick on an empty queue, publishes, waits for a tick which saw the domain hold the change and only then queues it: the check has run with the change on its way and compared it with a state seen before it was published, by construction. The mutant above now dies in the first round of both cases; the first-sight mutant still dies in those two and in the throttle case.
|
Round 3 is on the branch as f203d97, on top of 95ea7fb. The previous-wait compare was not pinned - confirmed, and the diagnosis is exact: a delivery
Your mutant on f203d97: 8 ran, 2 failed, both in their first round - The description carries the new hand-over and the third mutant. |
Refs #963
A handler which is following is served by
MessageHandler.add()alone: the domain hands it everychange it receives, so an empty message queue means the consumer has everything the domain has.
fillLateQueue()is the only reader of the changelog and is not called again while the handlerfollows, so a change which reaches the changelog without reaching that queue is never sent again,
and the replication server considers the replica up to date for the rest of the session.
followingis a one-way door, and that is what this PR closes.
What this explains, and what it does not
The run in the issue -
ReSyncTest.testResyncAfterRestore, a replica reconnecting after a restoreannouncing a state behind the entry added in between, then 30 s with nothing on the wire - is
consistent with such a miss, and the analysis there establishes that the change was in the
changelog and the announced state was behind it. It does not establish that a miss of this shape is
what happened, and one later occurrence says it was not.
The fifth occurrence in the table on the issue landed on the head of this branch, which carries the
diagnostic added here. In the artifacts of
attempt 1 of run 34241837159
WARN_CHANGELOG_READ_AGAIN_FOR_MISSING_CHANGESnever appears, while WARNING-severity lines fromthat test are in
logs/errors; the writer of RS(104) sat in the wait loop which calls the check forthe whole 30 s; the generation id matched on both connects, so
isFedByTheDomain()was true; and thethrottle cannot account for it, since
lastMissingChangesDomainStatestarts null, the check fires onthe second consecutive wait and there were some sixty waits to spare. So the domain was never seen
ahead of the handler, which is only possible if the change never reached the changelog of that RS
at all.
That leaves the candidate @maximthomas raised on the issue - the change lost before it reaches the
replication server - tied with a loss on the replica side, and #1015 (the RS-side state dump on a
failing replication test) is what separates them. The linking keyword here is therefore
Refsrather than
Fixes: #963 stays open until the cause of that failure is located.What this PR stands on is the invariant rather than that run: a following handler whose queue is
empty while the domain is ahead of it has lost a change which is in the changelog and which nothing
else will ever send it. And the warning is the diagnostic the issue asks for - by construction it is
only written when the invariant is already broken, and it carries both states. It has already earned
its keep by ruling one of the three candidates out of a live run.
The change
While waiting on an empty queue, the handler of a directory server now compares its state with the
state of the domain and goes back to the catch-up path when it is behind, which reads the changelog
again and delivers what is missing. The comparison is the in-memory
ServerState.cover()one, so itcosts no cursor.
Two things keep it from firing when it should not:
The state of the domain is advanced by
publishUpdateMsg()slightly beforeaddUpdate()queuesthe change, so what the domain received since the previous wait may simply be on its way; what it
held a whole wait ago and is still neither queued nor in the state of the handler is missing.
Comparing with that state rather than counting the waits which saw the domain ahead means a
change on its way is left alone even next to a gap the changelog was already read for.
does not close is reported once and retried when the domain receives something new, not on every
tick.
Only the handlers of directory servers are checked (
isFedByTheDomain()), and only while the domainfeeds them. A peer replication server is handed nothing but the changes of the directory servers
connected to this one: what a third replication server relayed never reaches its queue nor its
state, so the domain is always ahead of it, and reading the changelog on its behalf would send it
what it already holds - on every change relayed by a third RS, in a mesh of three or more (found in
review). A replica with a bad generation id, or one being initialized, is likewise legitimately
behind: reading the changelog for it would move its state past changes the writer then drops, which
is the loss this PR is about, in the other direction.
Testing
MissedUpdateRecoveryTestwrites a change straight into the changelog throughChangelogDB.getReplicationDomainDB().publishUpdateMsg(), bypassingReplicationServerDomain.put()and therefore the
add()it does on every connected handler. That is the state a missed deliveryleaves behind: the record is in the changelog, the handler is following, its queue is empty and its
state is behind.
aFollowingReplicaIsSentAChangeItsQueueNeverReceived- fails on master (the replica was never sent the change the changelog holds for it), passes here. The warning is written once and namesboth states.
aChangeOnItsWayToTheQueueIsNotReadAgain- a change handed to the queue once a wait of the handlerhas seen it in the changelog is sent from the queue, once, and nothing is read again.
aChangeTheDomainQueuesKeepsTheReplicaFollowing- the ordinary path throughput().aGapAlreadyReadForIsNotReadAgainUntilTheDomainAdvances- the throttle: a gap reopened by hand(
ServerState.removeCSN(), since a changelog holding a change it cannot yield cannot be builtfrom outside) is not read for again while the domain holds nothing new, and is once it does.
aChangeOnItsWayIsNotReportedMissingNextToAGapAlreadyReadFor- next to such a gap, a change onits way still comes from the queue, and the warning which follows the advance of the domain names
a state of the replica which holds it.
aReplicaTheDomainDoesNotFeedIsLeftAlone,aReplicaBeingInitializedIsLeftAlone- a replica with amismatching generation id, or in full update, must not have its state moved past a change nobody
sends it. Both pass before and after; they pin the guard.
aPeerReplicationServerIsLeftAlone- a mesh of three replication servers with the replica behindthe third: the handler of one peer stays on its queue and logs nothing for the change the other
peer relayed. Red on the first head of this PR.
The two tests which hold a change on its way hand it to the queue by ticks rather than by wall clock
(round 3):
publishThenQueueLate()waits for a wait of the handler on an empty queue, publishes,waits for a wait which saw the domain hold the change -
MessageHandler.getDomainStateAtPreviousWait(),package private for that - and only then queues it. The check has therefore run with the change on
its way and compared it with a state seen before the publish, by construction. The 400 ms hold it
replaces never contained a tick: a delivery from the queue re-phases the 500 ms wait, so the tick
always landed after the hand-over.
The tests which are green without the guard, the wait-back comparison or the throttle were each run
against a mutant: a guard ignoring both statuses fails the two guard cases; a check firing on first
sight without the throttle fails the on-its-way and throttle cases; a check comparing with the
current state of the domain instead of the one seen at the previous wait fails both on-its-way cases
in their first round.
Ran together with the tests around the change:
AssuredReplicationServerTest,ReplicationServerTest,ReSyncTest,ReplicationServerShutdownSyncTest,HandshakeAbortGenerationIdTest,HandshakeAbortRegistrationTest- 395 tests, no failures (ReSyncTestrerun alone after the admin-port collision of consecutive forks took its setUp down in the combined run).Rebase
Rebased onto master at 13d57e0 (95ea7fb). The only conflict, both times, was the tail of
replication.properties: first #945 putWARN_REPLAY_NOT_DRAINED_319andWARN_REPLAY_DRAIN_INTERRUPTED_320where this PR adds its message, then #959 putERR_REPLICATION_DOMAIN_CONFIG_CHANGE_FAILED_326andNOTE_REPLICATION_DOMAIN_SESSION_NOT_RESTARTED_327there. All sides are kept, the message of thisPR directly after 320; no ordinal is claimed twice. Not a line of Java moved with either rebase -
the Java files of 95ea7fb are byte-identical to the reviewed head a635266; f203d97 then adds the
accessor and the tick-anchored hand-over of round 3. On the rebased head,
MissedUpdateRecoveryTest,ReplicationServerTest,ReSyncTestandReplicationServerShutdownSyncTest- 30 tests, nofailures; on f203d97,
MissedUpdateRecoveryTesttwice - 8 tests, no failures - and red againstboth mutants as described above.
Ordinal
WARN_CHANGELOG_READ_AGAIN_FOR_MISSING_CHANGES_321, moved off 310 in ef79edc. Six open branches hadeach read 310 as the first ordinal free in master and taken it, and git merges those additions
without reporting a conflict - they land in different places in the file - so the duplicate would
only have surfaced afterwards, as two unrelated messages sharing one support ID. The generator does
not check either: it keys on name and ordinal together, so both compile. The open PRs which add to
replication.propertieshold 310-325 with nothing claimed twice; #945 has landed since, so 319-320are in master now and 321 sits directly after them.