* A change made it and nothing is failing anymore, so the backend is serving again and * the session is not being restarted in a row. While something is still failing, a @@ -3400,12 +3419,19 @@ private void recordChangeResolved(CSN csn) * applied here fails alone, among changes which replay perfectly well, and letting * those reset the wait would have this domain tear its session down every second for as * long as that one change takes to be given up on. + *
+ * The deliveries which were folded into no warning go with the backoff rather than into + * the next warning: a line logged when this domain fails again - a day later, over + * another change - would have them read as deliveries of that failure. How long the + * warning is not logged again is deliberately left alone, so that a backend which fails + * and recovers in turn is not one warning per failure again. */ - private void resetSessionRestartBackoff() + private void resetReplayFailureTracking() { if (!remotePendingChanges.hasFailingChanges()) { consecutiveSessionRestarts.set(0); + foldedReplayRetryWarnings.set(0); } } @@ -3468,7 +3494,62 @@ private void sendUnreplayedChangeAlert(LocalizableMessage cause) @VisibleForTesting public void resetUnreplayedChangeAlertThrottle() { - lastUnreplayedChangeAlertTime.set(UNREPLAYED_CHANGE_ALERT_NEVER_SENT); + lastUnreplayedChangeAlertTime.set(REPLAY_FAILURE_NEVER_REPORTED); + } + + /** + * Warns that this replica could not replay a change and is asking for it again. + *
+ * The warning is not logged again for {@link #REPLAY_RETRY_WARNING_INTERVAL_IN_MS}, + * for the reason the alert above is not sent again and for one more: a change which + * keeps failing is delivered again every {@link #MAX_REPLAY_RETRY_DELAY_IN_MS} at the + * slowest, so one line per delivery is the same warning every ten seconds, for as long + * as the give-up budget of the change lasts - a budget the administrator sets, and + * which can be unlimited (issue #942). + *
+ * The deliveries which are not warned about are counted rather than dropped, so the + * line which is logged says how many of them it stands for, and they are traced for + * whoever turns the replication debug logging on. + * + * @param csn the CSN of the change which could not be replayed + * @param failure how long, and over how many deliveries, its replay has been failing + */ + private void logReplayRetryWarning(CSN csn, RemotePendingChanges.ReplayFailure failure) + { + final long now = monotonicNowInMs(); + final long lastLogged = lastReplayRetryWarningTime.get(); + if (now - lastLogged >= REPLAY_RETRY_WARNING_INTERVAL_IN_MS + && lastReplayRetryWarningTime.compareAndSet(lastLogged, now)) + { + logger.warn(WARN_REPLAY_RETRYING_CHANGE, csn, getBaseDN(), failure.getAttempts(), + failure.getFailingForMs(), foldedReplayRetryWarnings.getAndSet(0)); + } + else + { + /* + * A failure which loses the race against the thread which is logging right now is + * counted for the next line rather than for the one being written: what the count + * says is how many deliveries went unlogged, and carrying one of them over to the + * next interval says nothing else. + */ + foldedReplayRetryWarnings.incrementAndGet(); + logger.trace("Could not replay change %s in domain %s: delivery %d, failing for %d ms", + csn, getBaseDN(), failure.getAttempts(), failure.getFailingForMs()); + } + } + + /** + * Lets the next change whose replay fails be warned about straight away. + *
+ * Only there for the tests which check the warning: they must not be at the mercy of + * the warning another test logged less than + * {@link #REPLAY_RETRY_WARNING_INTERVAL_IN_MS} ago. + */ + @VisibleForTesting + public void resetReplayRetryWarningThrottle() + { + lastReplayRetryWarningTime.set(REPLAY_FAILURE_NEVER_REPORTED); + foldedReplayRetryWarnings.set(0); } /** @@ -3584,9 +3665,12 @@ private boolean recoverFromReplayFailure( * Not on the road out of a JVM which has run out of memory: building this line asks * it for the memory it has just refused, and the ack of the delivery already says * that the change was not applied. The constant that ack carries exists for the same - * reason. + * reason. The throttle is left alone as well - the trace line a folded delivery is + * written to asks for that memory too, and this delivery is not one which goes + * unlogged: the error ends the replay thread, and the uncaught exception handler of + * DirectoryThread writes the line and raises the alert for it. */ - logger.warn(WARN_REPLAY_RETRYING_CHANGE, csn, getBaseDN(), failure.getAttempts()); + logReplayRetryWarning(csn, failure); } /* * This change is not owned by anyone anymore, so the session has to be restarted for diff --git a/opendj-server-legacy/src/messages/org/opends/messages/replication.properties b/opendj-server-legacy/src/messages/org/opends/messages/replication.properties index d5a7e69970..02046e7026 100644 --- a/opendj-server-legacy/src/messages/org/opends/messages/replication.properties +++ b/opendj-server-legacy/src/messages/org/opends/messages/replication.properties @@ -617,8 +617,9 @@ ERR_COULD_NOT_BIND_CHANGELOG_PORT_FREE_305=Nothing holds %s anymore : the port w NOTE_FULL_UPDATE_REMOTE_REQUEST_REJECTED_306=Cannot start total update \ in domain "%s" from this directory server DS(%d): rejecting the request from the remote directory server DS(%d): %s WARN_REPLAY_RETRYING_CHANGE_307=Could not replay change %s in domain "%s" (delivery %d, each \ - attempted several times in place). The change has not been recorded as replayed: restarting the \ - session to the replication server so that it is sent again + attempted several times in place, failing for %d ms). The change has not been recorded as \ + replayed: restarting the session to the replication server so that it is sent again. %d further \ + deliveries failed in this domain without being logged since the previous warning ERR_REPLAY_SKIPPING_CHANGE_308=Could not replay change %s in domain "%s": its replay has been \ failing for %d ms over %d deliveries, each attempted several times in place. The change is being \ skipped: this replica now diverges from the rest of the topology and must be reinitialized. \ diff --git a/opendj-server-legacy/src/test/java/org/opends/server/replication/UpdateOperationTest.java b/opendj-server-legacy/src/test/java/org/opends/server/replication/UpdateOperationTest.java index b791c2a7da..f006cd77ee 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/replication/UpdateOperationTest.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/replication/UpdateOperationTest.java @@ -23,6 +23,7 @@ import static org.forgerock.opendj.ldap.requests.Requests.*; import static org.forgerock.opendj.ldap.schema.CoreSchema.*; import static org.mockito.Mockito.*; +import static org.opends.messages.ReplicationMessages.*; import static org.opends.server.TestCaseUtils.*; import static org.opends.server.protocols.internal.InternalClientConnection.*; import static org.opends.server.replication.plugin.LDAPReplicationDomain.*; @@ -34,6 +35,7 @@ import java.util.ArrayList; import java.util.Collections; import java.util.HashSet; +import java.util.LinkedHashSet; import java.util.List; import java.util.Set; import java.util.concurrent.TimeoutException; @@ -3615,6 +3617,161 @@ public CSN getCSN() } } + /** + * Test case for [Issue 942]: a change whose replay keeps failing is warned about once + * per interval rather than once per delivery. + *
+ * The session is left down for ten seconds at the longest between two deliveries, so a + * warning per delivery is the same line every ten seconds for as long as the change is + * retried - and how long that is has been the administrator's to set since #901. + */ + @Test + public void aChangeWhichKeepsFailingIsWarnedAboutOncePerInterval() throws Exception + { + testSetUp("aChangeWhichKeepsFailingIsWarnedAboutOncePerInterval"); + logger.error(LocalizableMessage.raw( + "Starting replication test : aChangeWhichKeepsFailingIsWarnedAboutOncePerInterval")); + + final int serverId = 19; + ReplicationBroker broker = + openReplicationSession(baseDN, serverId, 100, replServerPort, 1000); + try + { + CSNGenerator gen = new CSNGenerator(serverId, 0); + + Entry tmp = TestCaseUtils.addEntry( + "dn: uid=user.942," + baseDN, + "objectClass: top", + "objectClass: person", + "objectClass: organizationalPerson", + "objectClass: inetOrgPerson", + "uid: user.942", + "cn: Aaccf Amar", + "sn: Amar"); + String uuid = getEntry(tmp.getName(), 1, true).parseAttribute("entryuuid").asString(); + + final LDAPReplicationDomain domain = MultimasterReplication.findDomain(baseDN, null); + /* + * The throttle is the domain's and the domain outlives the test methods: a change + * another test was retrying less than an interval ago would have the first warning + * of this one folded into its own. + */ + domain.resetReplayRetryWarningThrottle(); + final CSN csn = gen.newCSN(); + try + { + ShortCircuitPlugin.registerShortCircuit( + OperationType.DELETE, "PreParse", ResultCode.OTHER.intValue()); + broker.publish(new DeleteMsg(tmp.getName(), csn, uuid)); + + /* + * A delivery burns IN_PLACE_REPLAY_ATTEMPTS short circuits before the session is + * restarted and the change is asked for again, so three times that many of them + * are three deliveries which failed - and three warnings, before this one was + * throttled. The give-up budget is minutes and the interval is a minute, so the + * change is still being retried by then and the deliveries all fall into one + * interval. + */ + TestTimer timer = new TestTimer.Builder() + .maxSleep(60, SECONDS) + .sleepTimes(100, MILLISECONDS) + .toTimer(); + timer.repeatUntilSuccess(new CallableVoid() + { + @Override + public void call() throws Exception + { + assertTrue(ShortCircuitPlugin.getShortCircuitCount(OperationType.DELETE, "PreParse") + > 3 * IN_PLACE_REPLAY_ATTEMPTS, + "the change was not delivered again after its replay failed"); + } + }); + assertEquals(replayRetryWarnings(csn).size(), 1, + "a change which keeps failing must be warned about once per interval, not once per delivery"); + + /* + * Once the interval has passed the change is warned about again: a domain which + * never gives up - the budget can be unlimited - must not go silent over a change + * it is still asking for, and the line which comes says how many deliveries went + * unlogged in the meantime. + */ + TestTimer intervalTimer = new TestTimer.Builder() + .maxSleep(120, SECONDS) + .sleepTimes(500, MILLISECONDS) + .toTimer(); + intervalTimer.repeatUntilSuccess(new CallableVoid() + { + @Override + public void call() throws Exception + { + assertEquals(replayRetryWarnings(csn).size(), 2, + "a change which is still failing an interval later must be warned about again"); + } + }); + Assertions.assertThat(replayRetryWarnings(csn).get(1)) + .as("the warning must say how many failed deliveries it stands for") + .containsPattern("[1-9]\\d* further deliveries failed"); + } + finally + { + ShortCircuitPlugin.deregisterShortCircuit(OperationType.DELETE, "PreParse"); + } + + /* + * The backend serves again, so the delivery which comes next replays the change: a + * change left failing here would be the next test's, holding its ServerState back + * and its session restart backoff up. + */ + TestTimer replayTimer = new TestTimer.Builder() + .maxSleep(60, SECONDS) + .sleepTimes(200, MILLISECONDS) + .toTimer(); + replayTimer.repeatUntilSuccess(new CallableVoid() + { + @Override + public void call() throws Exception + { + assertTrue(domain.getServerState().cover(csn), + "the change must be replayed once the backend serves again"); + } + }); + } + finally + { + broker.stop(); + } + } + + /** + * Returns the warnings this replica logged about the provided change being asked for + * again, oldest first. + *
+ * The error log of the test server is written to a writer which keeps every record, so + * the warnings about one change are the records which carry the ordinal of the message + * and the CSN of the change. + *
+ * The test server registers two error log publishers over that one writer, so it keeps
+ * every record twice: what is returned here is the records which differ. Two warnings
+ * about the same change never read the same - the delivery they report, how long the
+ * change has been failing and how many deliveries were folded into them all move on.
+ *
+ * @param csn the CSN of the change whose replay keeps failing
+ * @return the warnings which name it, in the order they were logged
+ */
+ private static List