Repository navigation
dsreplication initialize fails hard when a total-update request gets no answer: the peers-not-found retry can never fire #995
Description
Activity
Confirmed against the code
Both halves of the classification failure reproduce by inspection, and each step is pinned:
- The value read is the first one, and it never changes.
firstValueAsString()(ConnectionUtils.java:42-46) returnsattr.firstValueAsString(). The server keepsds-task-log-messagein insertion order —Task.addLogMessage()appends through anAttributeBuilderwhose backingSmallSetis aLinkedHashMap(SmallSet.java:49) — andTaskThread.java:178logsNOTE_TASK_STARTEDfrom the task thread, with the task already associated, beforetask.execute(). So the first value is fixed for the life of the task, which is exactly what the failing run prints as "Last log details". - The match string cannot occur.
Task.buildLogMessage()rendersmsgID=<resourceName>-<ordinal>(Task.java:850-853);InstallerHelper.java:688looks for"=" + ordinal, i.e.=47. Ordinal 47 is confirmed byreplication.properties:90, the rendered form by the failing run itself (msgID=org.opends.messages.backend-413). - Exit code 12 is the proof.
Installer.java:4402→ApplicationException→ReplicationCliMain.java:6604-6607→ERROR_INITIALIZING_BASEDN_GENERIC; five exhausted attempts would have givenINITIALIZING_TRIES_COMPLETED(ReplicationCliReturnCode.java:59,63).
Correction to suggested action 1
"test every value of the attribute, or the last one" — the last one does not work either.
TaskThread.run()logsNOTE_TASK_FINISHEDimmediately aftertask.execute()returns (TaskThread.java:180-182), still on the task thread, whereas the terminalds-task-stateis only written afterwards byTaskScheduler.threadDone()(TaskScheduler.java:541-542). By the time a poll observesSTOPPED_BY_ERROR, the last value is therefore always the finished notice:[...] severity="NOTICE" msgCount=N msgID=org.opends.messages.backend-414 message="Initialize From Replica task quicksetup-initialize3 finished execution in the state Stopped by error"and the cause sits in the middle. Classification must scan all values. For the text shown to the user ("Last log details"), the useful pick is the last
severity="ERROR"value, falling back to the last value —severity="<name>"is written by our ownTask.buildLogMessage(), so that token is stable.Suggested action 2 covers only one of the two producers of this error
Matching the rendered message id restores the retry for the watchdog error raised locally by
ReplicationDomain.java:2466, which keeps the descriptor and therefore renders asmsgID=org.opends.messages.replication-47.It does not restore it for the other producer,
ReplicationServerDomain.replyWithUnreachablePeerMsg()(:1521, and theforwardMsgToAllServers()failure path at:1563). Those compose the text with aLocalizableMessageBuilderand ship it as anErrorMsg, which carries only the rendered string; on the requester sideprocessErrorMsg()(ReplicationDomain.java:2044) wraps that raw text, and a raw descriptor hasresourceName = null, ordinal = -1(LocalizableMessageDescriptor.Raw→super(Void.class, null, null, -1)). The task line then readsmsgID=null--1, so no id-based predicate can recognise it. Recovering that case needs the message identity to survive the protocol hop (or a separate marker); worth a follow-up rather than a text match, which would be locale-dependent.The same defect also silences the task log of every dsreplication command
Because the first value never changes, the
if (logMsg != null && !logMsg.equals(lastLogMsg))guard fires exactly once per task, in all six polling loops:Installer.java:4359(initialize),:4558(reset-generation-id),ReplicationCliMain.java:1423(reset-change-number),:1577(purge-historical),:6737(pre/post external initialization),:6873(initialize-all). Every one of them logs and reports the "started execution" notice and nothing else, whatever the task did. That is why the failing run left no usable diagnostics, and by everyday impact it is the heavier half of this bug — the retry is only broken for one error, the diagnostics are broken for all of them.Two smaller notes
lastLogMsg == null || helper.isPeersNotFoundError(lastLogMsg)(Installer.java:4402,ReplicationCliMain.java:6908) classifies any failure without log messages as peers-not-found. Unreachable today (NOTE_TASK_STARTEDis always there), but it should not be inherited by the fix.- Retry budget: five attempts of up to 120 s plus the 0/3/6/9 s backoff is ~10.3 min, against
timeout-minutes: 30on the CI step (build.yml:295, normal duration ~4 min). Enabling the retry does not endanger the step, but a genuinely dead topology will take ~10 min to fail instead of 2. The watchdog bounds only the wait forInitializeTargetMsg, not the transfer, so a source that needs more than two minutes to start exporting would now be aborted five times in a row.
A fix along these lines (scan all values, classify on the rendered message id, report the last error-severity message, plus unit tests) is in preparation; the
ErrorMsgvariant above is left as a follow-up.Reacted by Maxim Thomas- The value read is the first one, and it never changes.
Summary
When a total-update request gets no answer,
dsreplication initializealways fails hard aftertwo minutes. The five-attempt retry the CLI implements for exactly this error can never run:
both of the conditions that would classify the failure as "peers not found" are broken. The
watchdog added in #864 therefore turns the silent hang of #861 into a hard, non-recoverable
error instead of the retry its recovery path was written for.
Occurrence
(
build-maven (ubuntu-latest, 17), step Test replication)step and passed in 3:25–3:42, so this is the intermittent race of dsreplication enable hangs initializing registration information when adding a third replica; CI Test replication step has no timeout #861, not a regression of
the branch being built.
The elapsed time is exactly 120 s, which is
InitializeTask.INITIALIZE_START_TIMEOUT_MS = 2 * 60 * 1000(InitializeTask.java:49).Analysis
dsreplication initializecreates taskquicksetup-initialize3on the destination server(
Installer.java:4277).InitializeTask.runTask()publishes anInitializeRequestMsgandwaits for the answering
InitializeTargetMsg(
ReplicationDomain.java:2399-2406).No answer arrived. The watchdog of [#861] Fail fast when a total update request gets no answer #864 fired:
InitializeTask.java:131→ReplicationDomain.abortStalledInitializeFromRemote()(:2454)→
ImportExportContext.abandonIfStalled()(:1264). The context is abandoned withERR_NO_REACHABLE_PEER_IN_THE_DOMAIN(ordinal 47) and the task endsSTOPPED_BY_ERROR.The CLI has a recovery path for precisely this error —
int nTries = 5with a 0/3/6/9 sbackoff (
ReplicationCliMain.java:6583, and:6636forinitialize-all), entered whenInstaller.initializeSuffix()throwsPeerNotFoundException. It cannot be entered, fortwo independent reasons:
Installer.java:4359(and the four siblingloops at
Installer.java:4558,ReplicationCliMain.java:1423,:1577,:6737,:6873)read
firstValueAsString(sr, "ds-task-log-message").ds-task-log-messageismulti-valued (
resource/schema/02-config.ldif:465, noSINGLE-VALUE) andTask.addLogMessage()appends one value per message, so the value tested is always thefirst one —
NOTE_TASK_STARTED, "… started execution". The error message logged byInitializeTask.runTask()and routed into the task entry byErrorLogger.log()(
ErrorLogger.java:104-112) is a later value and is never looked at. This is visible inthe log above: the CLI prints the start notice as "Last log details".
InstallerHelper.isPeersNotFoundError()(
InstallerHelper.java:686) testslogMsg.contains("=" + ERR_NO_REACHABLE_PEER_IN_THE_DOMAIN.ordinal()), i.e. the literal"=47". A message rendered intods-task-log-messagecarries the id asmsgID=org.opends.messages.replication-47, which contains-47, never=47. So thepredicate returns
falseeven when handed the right value.Consequently
Installer.java:4402takes theelsebranch, throwsApplicationException,and
ReplicationCliMainmaps it toERROR_INITIALIZING_BASEDN_GENERIC= 12. Theobserved exit code 12 is the proof that the retry branch was not taken: had the five
attempts been made and exhausted, the exit code would have been
INITIALIZING_TRIES_COMPLETED= 10 (ReplicationCliReturnCode.java:59,63).The CI step runs under
bash -e, so the job aborted beforeTest on Windowsand before theartifact upload; no server logs were kept for the failing run.
Relation to #861
#861 reported the same underlying race (a total-update request or its answer silently lost with
no error reported back). It was closed with #864 (fail fast after two minutes) and #862
(
timeout-minuteson the CI step) — both of which bound the damage but neither of whichaddresses the loss itself. Its second suggested action, "Investigate the race in the
ADS/registration-data total update", is still open work.
Suggested actions
value of
ds-task-log-message— e.g. test every value of the attribute, or the last one.isPeersNotFoundError()to match the rendered form of the message id (-47, or better,match on the message id rather than on a hand-built substring).
isPeersNotFoundError()with a realistic log line(
… msgID=org.opends.messages.replication-47 message="Domain …"); it returnsfalsetoday.InitializeRequestMsg/InitializeTargetMsgbehind dsreplication enable hangs initializing registration information when adding a third replica; CI Test replication step has no timeout #861.