Skip to content

Commit 3847874

Browse files
authored
Wait for an in-flight replay before closing the log watcher (#1347)
## Motivation When a replica shuts down, `PathChildrenCache.close()` cancels its in-flight tasks with an interrupt. If a replay was waiting on `delegate.execute(...)` at that moment, the command had already been applied to the local data but `lastReplayedRevision` was never advanced, because it is updated only on the success path. The replica is then left with local data ahead of `<dataDir>/last_revision`, and the next start-up replays the same revision again. Re-applying a command whose effect is already in the local data fails, so the replica enters read-only mode and needs a manual re-sync. ``` [INFO ] [command-executor-shutdown] Closing the log watcher [ERROR] [zookeeper-log-watcher-1-1] Failed to replay a log at revision N; entering read-only mode. java.lang.InterruptedException at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:386) at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073) at ...ZooKeeperCommandExecutor.replayLogs(ZooKeeperCommandExecutor.java:820) at ...ZooKeeperCommandExecutor.childEvent(ZooKeeperCommandExecutor.java:885) at ...PathChildrenCache.lambda$callListeners$1(PathChildrenCache.java:529) ``` ## Modifications - Wait for an in-flight replay before closing the log watcher, by acquiring the same monitor that `replayLogs()` holds. Releasing it is safe because `listenerInfo` is already null, so a replay that starts afterwards returns before executing anything. - Move the log watcher shutdown ahead of `delegate.stop()`. The barrier waits for a replay that is itself waiting on the delegate, so the delegate must still be running. This also matches the drain that `shutdown(executor)` already performs for the command executor threads. `logWatcher.close()` still runs before `shutdown(logWatcherExecutor)`: reversing the two would let `PathChildrenCache` keep submitting to an already shut-down executor, because `submitToExecutor()` only guards on its own state, which flips in `close()`. - Wait uninterruptibly for the replay result, as a safeguard on the line where the failure occurred. - Log the last replayed revision once the replay is drained. Note this covers a graceful shutdown only. A `SIGKILL` between the local apply and the progress update leaves the same divergence; making the replay idempotent is a separate topic. ## Result - A replica that shuts down while replaying no longer leaves its local data ahead of its recorded replication progress, so it no longer enters read-only mode on the next start-up.
1 parent f8a443c commit 3847874

2 files changed

Lines changed: 74 additions & 3 deletions

File tree

server/src/main/java/com/linecorp/centraldogma/server/internal/replication/ZooKeeperCommandExecutor.java

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -680,14 +680,21 @@ private void stopLater() {
680680
protected void doStop(@Nullable Runnable onReleaseLeadership,
681681
@Nullable Runnable onReleaseZoneLeadership) throws Exception {
682682
canReplicate = false;
683+
// Stop accepting new replay logs.
683684
listenerInfo = null;
685+
684686
logger.info("Stopping the worker threads");
685687
boolean interrupted = shutdown(executor);
686688
logger.info("Stopped the worker threads");
687689

688690
try {
689-
logger.info("Stopping the delegate command executor");
690-
delegate.stop();
691+
// A replay holds this monitor until it records its progress; close() would interrupt it.
692+
logger.info("Waiting for an in-flight replay to finish");
693+
synchronized (this) {
694+
logger.info("No replay in flight; last replayed revision: {}", lastReplayedRevision);
695+
logger.info("Stopping the delegate command executor");
696+
delegate.stop();
697+
}
691698
logger.info("Stopped the delegate command executor");
692699
} catch (Exception e) {
693700
logger.warn("Failed to stop the delegate command executor {}: {}", delegate, e.getMessage(), e);
@@ -817,7 +824,9 @@ private synchronized void replayLogs(long targetRevision, boolean force) {
817824
l = loadLog(nextRevision);
818825
final Command<?> command = l.command();
819826
final Object expectedResult = l.result();
820-
final Object actualResult = delegate.execute(REPLAY_CONTEXT, command).get();
827+
// An interrupt here would split the local apply from updateLastReplayedRevision() below.
828+
final Object actualResult =
829+
Uninterruptibles.getUninterruptibly(delegate.execute(REPLAY_CONTEXT, command));
821830

822831
if (!Objects.equals(expectedResult, actualResult)) {
823832
throw new ReplicationException(

server/src/test/java/com/linecorp/centraldogma/server/internal/replication/ZooKeeperCommandExecutorTest.java

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -748,6 +748,68 @@ void inFlightCommandOnStopIsRecordedAndNotReplayed() throws Exception {
748748
}
749749
}
750750

751+
/**
752+
* A replay still in flight when the executor stops must finish and record its progress durably,
753+
* because closing the log watcher cancels its tasks with an interrupt. Otherwise the command is
754+
* applied to the local data while last_revision is not advanced, and the next start-up applies it
755+
* a second time.
756+
*/
757+
@Test
758+
@Timeout(120)
759+
void inFlightReplayOnStopIsRecordedAndNotReplayed() throws Exception {
760+
final CountDownLatch replayEntered = new CountDownLatch(1);
761+
final CountDownLatch proceed = new CountDownLatch(1);
762+
final AtomicInteger replayCount = new AtomicInteger();
763+
final AtomicInteger replicaIndex = new AtomicInteger();
764+
final Supplier<Function<Command<?>, CompletableFuture<?>>> delegateSupplier = () -> {
765+
final boolean replaying = replicaIndex.getAndIncrement() == 1;
766+
final Function<Command<?>, CompletableFuture<?>> base = newMockDelegate();
767+
return command -> {
768+
if (replaying && command != null && command.type() == CommandType.CREATE_REPOSITORY) {
769+
// Park inside replayLogs() so we can stop while the replay is in flight.
770+
replayCount.incrementAndGet();
771+
replayEntered.countDown();
772+
return CompletableFuture.supplyAsync(() -> {
773+
try {
774+
proceed.await();
775+
} catch (InterruptedException e) {
776+
throw new RuntimeException(e);
777+
}
778+
return null;
779+
}, CommonPools.blockingTaskExecutor());
780+
}
781+
return base.apply(command);
782+
};
783+
};
784+
785+
try (Cluster cluster = Cluster.builder().numReplicas(3).build(delegateSupplier)) {
786+
final Replica origin = cluster.get(0);
787+
final Replica replaying = cluster.get(1);
788+
origin.commandExecutor().execute(Command.createProject(Author.SYSTEM, "p")).join();
789+
await().untilAsserted(() -> assertThat(replaying.localRevision()).isEqualTo(0L));
790+
791+
// Park the replay of revision 1, then stop while it is in flight.
792+
origin.commandExecutor().execute(Command.createRepository(Author.SYSTEM, "p", "r")).join();
793+
assertThat(replayEntered.await(10, TimeUnit.SECONDS)).isTrue();
794+
final CompletableFuture<Void> stopFuture = replaying.commandExecutor().stop();
795+
// The shutdown must not finish while the replay is parked; that is the barrier doing its job.
796+
assertThatThrownBy(() -> stopFuture.get(3, TimeUnit.SECONDS))
797+
.isInstanceOf(TimeoutException.class);
798+
proceed.countDown();
799+
stopFuture.join();
800+
801+
// The replay finished before the log watcher was closed, so its progress is durable.
802+
assertThat(replaying.localRevision()).isEqualTo(1L);
803+
804+
// Catch up on a later revision to prove revision 1 was not applied a second time.
805+
replaying.commandExecutor().start().join();
806+
origin.commandExecutor().execute(Command.createProject(Author.SYSTEM, "p2")).join();
807+
await().untilAsserted(() -> assertThat(replaying.localRevision()).isEqualTo(2L));
808+
assertThat(replayCount).hasValue(1);
809+
assertThat(replaying.commandExecutor().isWritable()).isTrue();
810+
}
811+
}
812+
751813
private static <T> void awaitUntilReplicated(Cluster cluster, Command<T> command) {
752814
for (int i = 0; i < cluster.size(); i++) {
753815
final Replica replica = cluster.get(i);

0 commit comments

Comments
 (0)