[#942] Warn once per interval that a change is being retried, not once per delivery - #982
Conversation
124cc80 to
7057541
Compare
|
Rebased onto master ( The conflict the description promised never came: #944 landed first, and the What master changed in
|
7057541 to
393c43b
Compare
|
Rebased onto master ( The only file both sides touched is The red run on the pre-rebase head is not this branch. Verified on the rebased branch rather than on the old head:
|
393c43b to
afd918c
Compare
|
Rebased onto master ( Two conflicts this time, both with what master added next to the lines this branch edits rather
#944 landed in this window. The note on the first rebase said it had landed before One thing worth a look rather than a conflict: this branch's test and master's Verified on the rebased head: |
afd918c to
8461531
Compare
|
Rebased onto master ( One conflict this time, in
#928's test takes server 19 for its Verified on the rebased head: |
…ing retried, not once per delivery Fixes OpenIdentityPlatform#942. recoverFromReplayFailure() logged WARN_REPLAY_RETRYING_CHANGE for every delivery of a change whose replay failed. The session is left down for ten seconds at the longest between two deliveries, so a change which keeps failing had the same line logged every ten seconds for as long as it was retried - and since OpenIdentityPlatform#901 how long that is belongs to the administrator, "unlimited" included. The throttle takes the shape of the alert next to it, a timestamp and a CAS: one line per domain and per minute. Per domain rather than per change, unlike what the issue sketched - the cause which makes one change unreplayable makes every change in flight unreplayable, and a replica whose ServerState is held back by the barrier change is sent every change which follows it over and over, so a per-change throttle would still leave one line per change accumulated since the outage began. The deliveries which are not logged are counted rather than dropped: the line which is logged says how many of them it stands for and how long the change has been failing, and the folded ones are traced for whoever turns replication debug logging on. The count goes back to zero where the session restart backoff does, so that a line logged over another failure a day later does not read as counting its deliveries; how long the warning is not logged again is deliberately left alone, or a backend which fails and recovers in turn is one warning per failure again. resetSessionRestartBackoff() is resetReplayFailureTracking() now that it clears both, and UNREPLAYED_CHANGE_ALERT_NEVER_SENT is REPLAY_FAILURE_NEVER_REPORTED, the one origin the alert and the warning are both measured from.
8461531 to
4730ee2
Compare
|
Rebased onto master ( Two conflicts this time, both with #922:
Verified on the rebased head, in one reactor built from the worktree: |
Fixes #942.
recoverFromReplayFailure()loggedWARN_REPLAY_RETRYING_CHANGEfor every delivery of a changewhose replay failed. The session is left down for ten seconds at the longest between two deliveries,
so a change which keeps failing had the same line logged every ten seconds - roughly 8600 lines a day
per stuck change - for as long as it was retried. Until #901 the five-minute constant bounded that;
now how long a change is retried belongs to the administrator,
unlimitedincluded.The throttle
The shape of the alert next to it (
UNREPLAYED_CHANGE_ALERT_INTERVAL_IN_MS): a timestamp and a CAS,one line per domain and per minute.
Per domain rather than per change, unlike what the issue sketched. The cause which makes one
change unreplayable makes every change in flight unreplayable, and the replica whose ServerState is
held back by the barrier change is sent every change which follows it again over every restarted
session: a per-change throttle would still leave one line per change and per interval, that is one
line per change accumulated since the outage began, growing with the outage. A domain-wide throttle
bounds the log whatever the number of failing changes and whatever the budget.
The deliveries which are not logged are counted rather than dropped, so the line which is logged says
how many of them it stands for and how long the change has been failing:
The folded ones are traced, so replication debug logging still has one line per delivery.
What comes with it
failing anymore - or a line logged over another failure a day later would read as counting that
failure's deliveries. How long the warning is not logged again is deliberately left alone: a
backend which fails and recovers in turn would otherwise be one warning per failure again.
resetSessionRestartBackoff()isresetReplayFailureTracking()now that it clears both, andUNREPLAYED_CHANGE_ALERT_NEVER_SENTisREPLAY_FAILURE_NEVER_REPORTED, the one origin the alertand the warning are both measured from.
ERR_REPLAY_SKIPPING_CHANGEis left alone: it is logged once per change given up on, which is oneline per divergence rather than one per delivery.
Tests
aChangeWhichKeepsFailingIsWarnedAboutOncePerInterval: a change which can never be replayed isdelivered again and again; three failed deliveries carry one warning, and the change is warned about
again once the interval has passed, with that line saying how many deliveries it stands for. The
warnings are read from the error log of the test server, counting the records which differ - it
registers two error log publishers over one writer, so every record is kept twice.
Both halves were watched failing before the fix went in: without the throttle the first assertion
sees three warnings (
expected [1] but found [6], the records doubled), and with a throttle whichlogs once and never releases the second sees one (
expected [2] but found [1]).Rebased on master
Rebased onto
776339a8c6. The diff against master is 256 added and 14 removed lines in the samethree files, and
git log origin/master..HEADshows the single commit. Three lines more than the fourrebases before it, all in one comment: the call this branch makes is now inside a guard master put
around the line it replaces, see below.
Onto
776339a8c6last, with two conflicts, both with #922:LDAPReplicationDomain: Replication: a change whose replay throws is left owned by a thread which is gone #922 wrapped thelogger.warn(WARN_REPLAY_RETRYING_CHANGE, ...)thisbranch turns into
logReplayRetryWarning(csn, failure)inif (!outOfMemory)- on the road out of aJVM which has run out of memory the line is not built, since building it asks for the memory the JVM
has just refused. Resolved as master's guard around this branch's call: on that road neither the
warning nor the trace of a folded delivery is built, and the delivery is not folded into the next
warning either - the error ends the replay thread, and the uncaught exception handler of
DirectoryThreadwrites the line and raises the alert for it, so it is not one which went unlogged.Master's comment says so, extended by that one sentence. The other hunk there was the constant each
side adds after
UNREPLAYED_CHANGE_ALERT_INTERVAL_IN_MS-REPLAY_RETRY_WARNING_INTERVAL_IN_MShere,
REPLAY_RAN_OUT_OF_MEMORYthere - both kept, this branch's first, next to the alert intervalits javadoc refers to as "the alert above".
UpdateOperationTest: Replication: a change whose replay throws is left owned by a thread which is gone #922 appended its tests and the message classesModifyMsgWhoseAckRunsOutOfMemory,AddMsgWhoseAckThrowsandAddMsgWhoseReplayIsUnwoundAfterItsAckat the point where this branch appends
aChangeWhichKeepsFailingIsWarnedAboutOncePerIntervalandits
replayRetryWarnings()helper, and the import each side adds next toCollections-HashSetthere,
LinkedHashSethere - collided with it. Resolved as master's file with this branch's testand helper inserted verbatim after master's classes, ahead of the
[Issue 908]tests, plus the twoimports this branch adds.
java.util.Setis master's now, which is the one line fewer in that file.replication.propertiesmerged on its own: #922 appended 315-317 and no ordinal is claimed twice.Nothing in the tree references
resetSessionRestartBackoff()orUNREPLAYED_CHANGE_ALERT_NEVER_SENT,and #922 added no call site of either. None of master's new tests reads
WARN_REPLAY_RETRYING_CHANGEfrom the error log, and none opens a broker of its own, so the note on server 19 below is unchanged.
The
catch (Error e)#922 put inside the replay takes the road of a failed replay, so a change whosereplay keeps throwing an
Erroris warned about through the throttle like any other, and thecatch (Throwable)aroundreplay()reaches the throttle through the samerecoverFromReplayFailure(). #976 (issue #949) is in the trace line ofpublishReplicaOfflineMsg(),in
PendingChangesand in the broker, away from the throttle.Onto
f559b0907abefore that, with one conflict, of the same shape as the previous one: #928 appendedaModifyWhoseEntryDNDoesNotParseIsReportedRatherThanThrownOntoUpdateOperationTestat the pointwhere this branch appends
aChangeWhichKeepsFailingIsWarnedAboutOncePerIntervaland itsreplayRetryWarnings()helper, and the import each side adds next toArrayList-Collectionsthere,
LinkedHashSethere - collided with it. Resolved as master's test followed by this branch'stest and helper verbatim, both imports kept.
LDAPReplicationDomainmerged on its own. Of the four master commits which touched it in this window(#943, #967, #928, #927) only #928 is in the replay path, and it is the one comparison turned round
into
SET_PERMISSIVE_MODIFY_FOR_DN.equals(...)insidereplay(); the others are in theconfiguration handling and the naming conflict resolution, away from the throttle.
replication.propertiesmerged with #911 and #943 without a conflict and has no ordinal claimedtwice. #928's test takes server 19 for its
CSNGeneratoronly and opens no broker, so the notebelow on server 19 is unchanged.
Onto
21d03d579bbefore that, with two conflicts, both with what master added next to the linesthis branch edits rather than with the throttle itself:
LDAPReplicationDomain: [#908] Wait for the changes being applied before a domain going down saves its ServerState #945 (issue Disabling a replication domain can drop a change a replay thread is applying #908) put thereplayLockand the replay drain timeout exactlywhere this branch rewrites the javadoc of
UNREPLAYED_CHANGE_ALERT_NEVER_SENTinto that ofREPLAY_FAILURE_NEVER_REPORTED. Master's block is kept whole and this branch's javadoc follows it,on the renamed constant. The rename and the two
resetReplayFailureTracking()call sites merged ontheir own; nothing in the tree references either old name anymore.
UpdateOperationTest: [#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 appendedaChangeBeingAppliedIsRecordedBeforeTheDomainIsDisabledand
theDomainStopsWaitingForAReplayWhichDoesNotFinishat the point where this branch appendsaChangeWhichKeepsFailingIsWarnedAboutOncePerInterval, and git interleaved the three. Resolved asmaster's file with this branch's test and its
replayRetryWarnings()helper inserted verbatim aheadof master's two tests, plus the three imports this branch adds.
#944 landed in that window, not before
2a7bb9d7edas an earlier version of this section said. Itsedit to
ERR_REPLAY_SKIPPING_CHANGE_308merged next to theWARN_REPLAY_RETRYING_CHANGE_307lineedited here on its own,
config.getReplayGiveUpDelay()is decided inrecoverFromReplayFailure()above the call to
logReplayRetryWarning()and does not touch it, and the "since #901" this branchrefers to now points at master rather than ahead of it.
This branch's test and master's
aChangeBeingAppliedIsRecordedBeforeTheDomainIsDisabledboth opentheir broker as server 19. Each stops it in a
finallyand the class already runs three tests asserver 2 in turn, so it is left as it is.
Onto
2a7bb9d7edand36d4af9bd7before that. The one conflict was in the imports ofUpdateOperationTest, where #941 broughtorg.mockito.Mockito.*,java.util.concurrent.TimeoutExceptionandAtomicReferencealongside theorg.opends.messages.ReplicationMessages.*andjava.util.Setthis branch adds - both sides kept.#971 rewrote
enable(), elsewhere inLDAPReplicationDomainthan the throttle.opendj-server-legacytest-compiles on the current head, and theUpdateOperationTestrun recordedabove is on it rather than on an older one: 32 tests, no failures, the case this branch adds among
them.