RATIS-2172. RaftServer may lose FollowerState #1166

133tosakarin · 2024-10-10T03:21:07Z

What changes were proposed in this pull request?

Move server.isRunning () check from LeaderElection to FollowerState to ensure that the server is ready when it becomes a candidate

What is the link to the Apache JIRA

https://issues.apache.org/jira/browse/RATIS-2172

133tosakarin · 2024-10-10T03:25:44Z

@szetszwo
Please review this PR

szetszwo

@133tosakarin , thanks a lot for working on this!

The code change looks good.

For the test, we already have a CodeInjectionForTesting mechanism. Please use it instead.

+++ b/ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerImpl.java
@@ -161,6 +161,7 @@ class RaftServerImpl implements RaftServer.Division,
   static final String APPEND_TRANSACTION = CLASS_NAME + ".appendTransaction";
   static final String LOG_SYNC = APPEND_ENTRIES + ".logComplete";
   static final String START_LEADER_ELECTION = CLASS_NAME + ".startLeaderElection";
+  static final String START_COMPLETE = CLASS_NAME + ".startComplete";
 
   class Info implements DivisionInfo {
     @Override
@@ -401,6 +402,7 @@ class RaftServerImpl implements RaftServer.Division,
 
     jmxAdapter.registerMBean();
     state.start();
+    CodeInjectionForTesting.execute(START_COMPLETE, getId(), null, role);
     startComplete.compareAndSet(false, true);
     return true;
   }

szetszwo

@133tosakarin , thanks for the update! Please see the comments inlined.

szetszwo · 2024-10-11T16:10:08Z

ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerImpl.java

@@ -1921,4 +1923,5 @@ void onGroupLeaderElected() {
  boolean isRunning() {
    return startComplete.get() && lifeCycle.getCurrentState() == State.RUNNING;
  }
+


Please revert this whitespace change.

szetszwo · 2024-10-11T16:10:27Z

ratis-server/src/test/java/org/apache/ratis/server/impl/MiniRaftCluster.java

-    startServers(servers.values());

+    startServers(servers.values());


Please revert this whitespace change.

szetszwo · 2024-10-11T16:10:49Z

ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerImpl.java

+    CodeInjectionForTesting.execute(START_COMPLETE, getId(), null, role);
    startComplete.compareAndSet(false, true);


Let's add a log message:

if (startComplete.compareAndSet(false, true)) { LOG.info("{}: Successfully started.", getMemberId()); }

szetszwo · 2024-10-11T16:16:19Z

ratis-server/src/test/java/org/apache/ratis/server/impl/LeaderElectionTests.java

+  @Test
+  public void testWaitServerReady() throws Exception {
+    LOG.info("Running testWaitServerReady");
+    int []arr = {1, 2, 3, 4, 5};
+    for (int i : arr) {
+      final MiniRaftCluster cluster = newCluster(1);
+      CodeInjectionForTesting.put(RaftServerImpl.START_COMPLETE, new SleepCode(1000));
+      cluster.start();
+      // Leader will be elected if the server is ready
+      Assertions.assertTrue(RaftTestUtil.waitForLeader(cluster).getId() != null);
+      cluster.shutdown();
+    }
+  }


For testing the bug, I suggest the following change to check the timestamps:

@Test public void testWaitServerReady() throws Exception { final int sleepMs = 1000 + ThreadLocalRandom.current().nextInt(1000); LOG.info("Running testWaitServerReady, sleep = {}ms", sleepMs); CodeInjectionForTesting.put(RaftServerImpl.START_COMPLETE, new SleepCode(sleepMs)); final MiniRaftCluster cluster = newCluster(1); final Timestamp startTime = Timestamp.currentTime(); cluster.start(); LOG.info("Cluster started at {}ms", startTime.elapsedTimeMs()); final RaftGroupId groupId = cluster.getGroupId(); final RaftServerImpl server = (RaftServerImpl) cluster.getServers().iterator().next().getDivision(groupId); final boolean isRunning = server.isRunning(); LOG.info("{} isRunning at {}ms? {}", server.getId(), startTime.elapsedTimeMs(), isRunning); // Leader will be elected if the server is ready Assertions.assertNotNull(waitForLeader(cluster), "No leader is elected."); final long elapsedMs = startTime.elapsedTimeMs(); // allow a small difference to tolerate system timer inaccuracy Assertions.assertTrue(elapsedMs > sleepMs - 10, () -> "elapseMs = " + elapsedMs + " but sleepMs = " + sleepMs); cluster.shutdown(); CodeInjectionForTesting.remove(RaftServerImpl.START_COMPLETE); }

With the new log message, we will see a lot of "first-election.timeout" logs and then "Successfully started". It seems good enough.

2024-10-11 09:12:52,420 [s0-impl-thread1] INFO util.CodeInjectionForTesting (LeaderElectionTests.java:execute(112)) - s0: Simulate RaftServer startup blocking, sleep 1686ms 2024-10-11 09:12:52,420 [s0-impl-thread1] INFO util.CodeInjectionForTesting (LeaderElectionTests.java:execute(112)) - s0: Simulate RaftServer startup blocking, sleep 1686ms 2024-10-11 09:12:52,571 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.min = 150ms (fallback to raft.server.rpc.timeout.min) 2024-10-11 09:12:52,571 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.max = 300ms (fallback to raft.server.rpc.timeout.max) 2024-10-11 09:12:52,758 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.min = 150ms (fallback to raft.server.rpc.timeout.min) 2024-10-11 09:12:52,758 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.max = 300ms (fallback to raft.server.rpc.timeout.max) ... 2024-10-11 09:12:53,925 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.min = 150ms (fallback to raft.server.rpc.timeout.min) 2024-10-11 09:12:53,925 [s0@group-C119E77DBEA6-FollowerState] INFO server.RaftServerConfigKeys (ConfUtils.java:logFallback(53)) - raft.server.rpc.first-election.timeout.max = 300ms (fallback to raft.server.rpc.timeout.max) 2024-10-11 09:12:54,107 [s0-impl-thread1] INFO server.RaftServer$Division (RaftServerImpl.java:start(407)) - s0@group-C119E77DBEA6: Successfully started.

Thanks for the advice provided

szetszwo · 2024-10-11T16:17:36Z

ratis-server/src/test/java/org/apache/ratis/server/impl/LeaderElectionTests.java

+  }
+
+  @Test
+  public void testAddServerForWaitReady() throws IOException, InterruptedException {


This test seems testing similar thing as the first test. Let's remove it?

I want to test to ensure that new members join and execute normally

szetszwo · 2024-10-11T16:18:52Z

ratis-server/src/test/java/org/apache/ratis/server/impl/LeaderElectionTests.java

+    int []arr = {1, 2, 3, 4, 5};
+    for (int i : arr) {
+      final MiniRaftCluster cluster = newCluster(1);
+      CodeInjectionForTesting.put(RaftServerImpl.START_COMPLETE, new SleepCode(1000));


Let add a CodeInjectionForTesting.remove method. Otherwise, it will affect other tests.

+++ b/ratis-common/src/main/java/org/apache/ratis/util/CodeInjectionForTesting.java @@ -55,6 +55,12 @@ public final class CodeInjectionForTesting { INJECTION_POINTS.put(injectionPoint, code); } + /** Remove an injection point. */ + public static void remove(String injectionPoint) { + final Code removed = INJECTION_POINTS.remove(injectionPoint); + LOG.debug("remove({}): {}", injectionPoint, removed); + } + /** Execute the injected code, if there is any. */ public static boolean execute(String injectionPoint, Object localId,

szetszwo

@133tosakarin , thanks for the update! Please see the comments inlined.

szetszwo · 2024-10-11T17:09:40Z

ratis-server/src/test/java/org/apache/ratis/server/impl/MiniRaftCluster.java

@@ -347,7 +347,6 @@ public void start() throws IOException {

    initServers();
    startServers(servers.values());
-


There still a whitespace change.

@133tosakarin , please take a look the file diff, there are two whitespace changes now.

Um, I'm sorry, I haven't had time to modify it yet

szetszwo · 2024-10-11T17:13:20Z

ratis-server/src/test/java/org/apache/ratis/server/impl/LeaderElectionTests.java

+        Assertions.assertTrue(reply.isSuccess());
+      }
+      // add 3 new servers and wait longer time
+      CodeInjectionForTesting.put(RaftServerImpl.START_COMPLETE, new SleepCode(2000));


Okay, I fine to keep this test. Then, we need to add CodeInjectionForTesting.remove at the end.

szetszwo

+1 the change looks good.

change server.isRunning() checking to FollowerState.

2fc4b9a

133tosakarin added 2 commits October 10, 2024 16:10

add unit test

981ddba

format

df6faf3

szetszwo reviewed Oct 10, 2024

View reviewed changes

133tosakarin added 4 commits October 11, 2024 11:36

add more test and use CodeInjectionForTesting instead runnable

69604ab

remove no usage method

ff334f4

rollback MiniRaftCluster.start

2c6efff

delay the startup time

542f81e

133tosakarin requested a review from szetszwo October 11, 2024 03:42

szetszwo reviewed Oct 11, 2024

View reviewed changes

add more detail information for test

df9da7f

szetszwo reviewed Oct 11, 2024

View reviewed changes

133tosakarin and others added 2 commits October 12, 2024 01:27

remove whitespace and codeInjectionCode

d187295

Revert white space changes from MiniRaftCluster.java

23aded8

szetszwo approved these changes Oct 11, 2024

View reviewed changes

szetszwo merged commit 62ae6d9 into apache:master Oct 11, 2024
12 checks passed

OneSizeFitsQuorum pushed a commit that referenced this pull request Oct 14, 2024

RATIS-2172. RaftServer may lose FollowerState (#1166)

b09bfe7

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

RATIS-2172. RaftServer may lose FollowerState #1166

RATIS-2172. RaftServer may lose FollowerState #1166

133tosakarin commented Oct 10, 2024

133tosakarin commented Oct 10, 2024

szetszwo left a comment

szetszwo left a comment

szetszwo Oct 11, 2024

szetszwo Oct 11, 2024

szetszwo Oct 11, 2024

szetszwo Oct 11, 2024

133tosakarin Oct 11, 2024

szetszwo Oct 11, 2024

133tosakarin Oct 11, 2024

szetszwo Oct 11, 2024

szetszwo left a comment

szetszwo Oct 11, 2024

szetszwo Oct 11, 2024

133tosakarin Oct 12, 2024

szetszwo Oct 11, 2024

133tosakarin Oct 11, 2024

szetszwo left a comment

		startServers(servers.values());

		startServers(servers.values());

		CodeInjectionForTesting.execute(START_COMPLETE, getId(), null, role);
		startComplete.compareAndSet(false, true);

		@@ -347,7 +347,6 @@ public void start() throws IOException {

		initServers();
		startServers(servers.values());

RATIS-2172. RaftServer may lose FollowerState #1166

RATIS-2172. RaftServer may lose FollowerState #1166

Conversation

133tosakarin commented Oct 10, 2024

What changes were proposed in this pull request?

What is the link to the Apache JIRA

133tosakarin commented Oct 10, 2024

szetszwo left a comment

Choose a reason for hiding this comment

szetszwo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

szetszwo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

szetszwo left a comment

Choose a reason for hiding this comment