[
https://issues.apache.org/jira/browse/RATIS-2137?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17874531#comment-17874531
]
Tsz-wo Sze commented on RATIS-2137:
-----------------------------------
[~lemony], you are right that LogAppenderDefault incorrectly handles the
INCONSISTENCY case. It should use the getNextIndexForInconsistency(..) method
in LogAppenderBase and then setNextIndex(..).
{code}
diff --git
a/ratis-server/src/main/java/org/apache/ratis/server/leader/LogAppenderDefault.java
b/ratis-server/src/main/java/org/apache/ratis/server/leader/LogAppenderDefault.java
index 432a4199..f75a80f8 100644
---
a/ratis-server/src/main/java/org/apache/ratis/server/leader/LogAppenderDefault.java
+++
b/ratis-server/src/main/java/org/apache/ratis/server/leader/LogAppenderDefault.java
@@ -23,6 +23,7 @@ import
org.apache.ratis.proto.RaftProtos.InstallSnapshotReplyProto;
import org.apache.ratis.proto.RaftProtos.InstallSnapshotRequestProto;
import org.apache.ratis.rpc.CallId;
import org.apache.ratis.server.RaftServer;
+import org.apache.ratis.server.raftlog.RaftLog;
import org.apache.ratis.server.raftlog.RaftLogIOException;
import org.apache.ratis.server.util.ServerStringUtils;
import org.apache.ratis.statemachine.SnapshotInfo;
@@ -34,6 +35,7 @@ import java.io.InterruptedIOException;
import java.util.Comparator;
import java.util.UUID;
import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
/**
* The default implementation of {@link LogAppender}
@@ -55,7 +57,7 @@ class LogAppenderDefault extends LogAppenderBase {
}
/** Send an appendEntries RPC; retry indefinitely. */
- private AppendEntriesReplyProto sendAppendEntriesWithRetries()
+ private AppendEntriesReplyProto sendAppendEntriesWithRetries(AtomicLong
requestFirstIndex)
throws InterruptedException, InterruptedIOException, RaftLogIOException {
int retry = 0;
@@ -78,9 +80,12 @@ class LogAppenderDefault extends LogAppenderBase {
return null;
}
- AppendEntriesReplyProto r = sendAppendEntries(request.get());
+ final AppendEntriesRequestProto proto = request.get();
+ final AppendEntriesReplyProto reply = sendAppendEntries(proto);
+ final long first = proto.getEntriesCount() > 0 ?
proto.getEntries(0).getIndex() : RaftLog.INVALID_LOG_INDEX;
+ requestFirstIndex.set(first);
request.release();
- return r;
+ return reply;
} catch (InterruptedIOException | RaftLogIOException e) {
throw e;
} catch (IOException ioe) {
@@ -164,9 +169,10 @@ class LogAppenderDefault extends LogAppenderBase {
}
// otherwise if r is null, retry the snapshot installation
} else {
- final AppendEntriesReplyProto r = sendAppendEntriesWithRetries();
+ final AtomicLong requestFirstIndex = new
AtomicLong(RaftLog.INVALID_LOG_INDEX);
+ final AppendEntriesReplyProto r =
sendAppendEntriesWithRetries(requestFirstIndex);
if (r != null) {
- handleReply(r);
+ handleReply(r, requestFirstIndex.get());
}
}
}
@@ -177,7 +183,8 @@ class LogAppenderDefault extends LogAppenderBase {
}
}
- private void handleReply(AppendEntriesReplyProto reply) throws
IllegalArgumentException {
+ private void handleReply(AppendEntriesReplyProto reply, long
requestFirstIndex)
+ throws IllegalArgumentException {
if (reply != null) {
switch (reply.getResult()) {
case SUCCESS:
@@ -200,7 +207,7 @@ class LogAppenderDefault extends LogAppenderBase {
onFollowerTerm(reply.getTerm());
break;
case INCONSISTENCY:
- getFollower().decreaseNextIndex(reply.getNextIndex());
+
getFollower().setNextIndex(getNextIndexForInconsistency(requestFirstIndex,
reply.getNextIndex()));
break;
case UNRECOGNIZED:
LOG.warn("{}: received {}", this, reply.getResult());
{code}
> Leader fails to send correct index to follower after timeout exception
> ----------------------------------------------------------------------
>
> Key: RATIS-2137
> URL: https://issues.apache.org/jira/browse/RATIS-2137
> Project: Ratis
> Issue Type: Bug
> Affects Versions: 2.5.1
> Reporter: Kevin Liu
> Priority: Major
> Attachments: image-2024-08-13-11-28-16-250.png
>
>
> *I found that after the following log, the follower became unavailable. The
> follower received incorrect entries repeatedly for about 10min, then got
> installSnapshot failed and started to election. After two hours, it succeed
> to install snapshot, but failed to updateLastAppliedTermIndex. After that, it
> repeated 'receive installSnapshot and installSnapshot failed' for several
> hours until I restarted the server.*
> 24/08/11 09:03:13,714 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: Failed appendEntries as the first entry (index
> 34795876) already exists (snapshotIndex: 34670809, commitIndex: 34795893)
> 24/08/11 09:03:13,714 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: inconsistency entries.
> Reply:3<-1#2559343:FAIL-t59,INCONSISTENCY,nextIndex=34795894,followerCommit=34795893,matchIndex=-1
> 24/08/11 09:03:13,715 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: Failed appendEntries as the first entry (index
> 34795875) already exists (snapshotIndex: 34670809, commitIndex: 34795893)
> 24/08/11 09:03:13,715 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: inconsistency entries.
> Reply:3<-1#2559406:FAIL-t59,INCONSISTENCY,nextIndex=34795894,followerCommit=34795893,matchIndex=-1
> *....(repeat 'Failed appendEntries')*
> 24/08/11 09:15:41,827 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: Failed appendEntries as the first entry (index
> 34465382) already exists (snapshotIndex: 34670809, commitIndex: 34795893)
> 24/08/11 09:15:41,827 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: inconsistency entries.
> Reply:3<-1#2892557:FAIL-t59,INCONSISTENCY,nextIndex=34795894,followerCommit=34795893,matchIndex=-1
> 24/08/11 09:15:42,230 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: receive installSnapshot:
> 3->1#0-t59,chunk:bbe49073-5dad-4499-9051-58a0e53b0658,0
> 24/08/11 09:15:42,231 ERROR [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: installSnapshot failed
> java.lang.IllegalStateException: 1@group-47BEDE733167 log's commit index is
> 34795893, last included index in snapshot is 34670057
> 24/08/11 09:15:42,233 WARN [nioEventLoopGroup-3-3] DefaultChannelPipeline: An
> exceptionCaught() event was fired, and it reached at the tail of the
> pipeline. It usually means the last handler in the pipeline did not handle
> the exception.
> java.lang.IllegalStateException: 1@group-47BEDE733167 log's commit index is
> 34795893, last included index in snapshot is 34670057
> 24/08/11 09:15:50,105 INFO [1@group-47BEDE733167-FollowerState]
> FollowerState: 1@group-47BEDE733167-FollowerState: change to CANDIDATE,
> lastRpcElapsedTime:7874610911ns, electionTimeout:3353ms
> 24/08/11 09:15:50,105 INFO [1@group-47BEDE733167-FollowerState] RoleInfo: 1:
> shutdown 1@group-47BEDE733167-FollowerState
> 24/08/11 09:15:50,105 INFO [1@group-47BEDE733167-FollowerState]
> RaftServer$Division: 1@group-47BEDE733167: changes role from FOLLOWER to
> CANDIDATE at term 59 for changeToCandidate
> 24/08/11 09:15:50,106 INFO [1@group-47BEDE733167-FollowerState]
> RaftServerConfigKeys: raft.server.leaderelection.pre-vote = true (default)
> 24/08/11 09:15:50,106 INFO [1@group-47BEDE733167-FollowerState] RoleInfo: 1:
> start 1@group-47BEDE733167-LeaderElection5
> 24/08/11 09:15:50,107 INFO [1@group-47BEDE733167-LeaderElection5]
> RaftServer$Division: 1@group-47BEDE733167: change Leader from 3 to null at
> term 59 for PRE_VOTE
> 24/08/11 09:15:50,107 INFO [1@group-47BEDE733167-LeaderElection5]
> LeaderElection: 1@group-47BEDE733167-LeaderElection5 PRE_VOTE round 0: submit
> vote requests at term 59 for 34233595:
> peers:[1|rpc:xxx:9862|admin:|client:xxx:9087|dataStream:|priority:0|startupRole:FOLLOWER,
>
> 2|rpc:xxx:9862|admin:|client:xxx:9087|dataStream:|priority:0|startupRole:FOLLOWER,
>
> 3|rpc:xxx:9862|admin:|client:xxx:9087|dataStream:|priority:0|startupRole:FOLLOWER]|listeners:[],
> old=null
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5]
> LeaderElection: 1@group-47BEDE733167-LeaderElection5: PRE_VOTE REJECTED
> received 2 response(s) and 0 exception(s):
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5]
> LeaderElection: Response 0: 1<-2#0:FAIL-t59
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5]
> LeaderElection: Response 1: 1<-3#0:FAIL-t59
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5]
> LeaderElection: 1@group-47BEDE733167-LeaderElection5 PRE_VOTE round 0: result
> REJECTED
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5]
> RaftServer$Division: 1@group-47BEDE733167: changes role from CANDIDATE to
> FOLLOWER at term 59 for REJECTED
> 24/08/11 09:15:50,110 INFO [1@group-47BEDE733167-LeaderElection5] RoleInfo:
> 1: shutdown 1@group-47BEDE733167-LeaderElection5
> 24/08/11 09:15:50,111 INFO [1@group-47BEDE733167-LeaderElection5] RoleInfo:
> 1: start 1@group-47BEDE733167-FollowerState
> 24/08/11 09:15:52,075 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: receive installSnapshot:
> 3->1#0-t59,chunk:802b8106-076b-4ffc-8cf1-1ace04952c7a,0
> 24/08/11 09:15:52,075 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: change Leader from null to 3 at term 59 for
> installSnapshot, leader elected after 1967ms
> 24/08/11 09:15:52,075 ERROR [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: installSnapshot failed
> java.lang.IllegalStateException: 1@group-47BEDE733167 log's commit index is
> 34795893, last included index in snapshot is 34670057
> *(repeat 'election, fail, install snapshot fail' for more than 2 hours)*
> *(still election fail, but this time install snapshot successfully, but
> failed to updateLastAppliedTermIndex)*
> 24/08/11 11:52:38,168 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: receive installSnapshot:
> 3->1#0-t59,chunk:dcc73f7c-c17d-44e5-96b6-f6f1570e68a7,0
> 24/08/11 11:52:38,168 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 1@group-47BEDE733167: change Leader from null to 3 at term 59 for
> installSnapshot, leader elected after 3610ms
> 24/08/11 11:52:39,434 INFO [nioEventLoopGroup-3-3] SnapshotManager:
> Installing snapshot:3->1#0-t59,chunk:dcc73f7c-c17d-44e5-96b6-f6f1570e68a7,0,
> to tmp
> dir:/data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/tmp/snapshot-dcc73f7c-c17d-44e5-96b6-f6f1570e68a7
> 24/08/11 11:52:39,455 INFO [nioEventLoopGroup-3-3] SnapshotManager: Installed
> snapshot, renaming temporary dir
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/tmp/snapshot-dcc73f7c-c17d-44e5-96b6-f6f1570e68a7
> to /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/sm
> 24/08/11 11:52:40,829 INFO [1@group-47BEDE733167-StateMachineUpdater]
> StateMachine: Reinitializing state machine.
> 24/08/11 11:52:40,829 INFO [nioEventLoopGroup-3-3] RaftLog:
> 1@group-47BEDE733167-SegmentedRaftLog: snapshotIndex: updateIncreasingly
> 33870802 -> 34870063
> 24/08/11 11:52:40,829 INFO [1@group-47BEDE733167-StateMachineUpdater]
> StateMachine: obsolete snapshot provided: (t:59, i:34670809)
> 24/08/11 11:52:40,829 INFO [nioEventLoopGroup-3-3] SegmentedRaftLogWorker:
> 1@group-47BEDE733167-SegmentedRaftLogWorker: flushIndex: setUnconditionally
> 34795893 -> 34870063
> 24/08/11 11:52:40,829 INFO [nioEventLoopGroup-3-3] SegmentedRaftLogWorker:
> 1@group-47BEDE733167-SegmentedRaftLogWorker: safeCacheEvictIndex:
> setUnconditionally 34783743 -> 34870063
> 24/08/11 11:52:40,829 INFO [1@group-47BEDE733167-StateMachineUpdater]
> StateMachineUpdater: 1@group-47BEDE733167-StateMachineUpdater: appliedIndex:
> setUnconditionally 34795893 -> 34670809
> 24/08/11 11:52:40,829 INFO [nioEventLoopGroup-3-3] SegmentedRaftLogWorker:
> 1@group-47BEDE733167-SegmentedRaftLogWorker: Closing segment
> log_inprogress_34783744 to index: 34795893
> 24/08/11 11:52:40,837 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: successfully install the
> entire snapshot-34870063
> 24/08/11 11:52:40,877 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: reply installSnapshot:
> 3<-1#0:OK-t59,SUCCESS,requestIndex=0
> 24/08/11 11:52:40,902 INFO [1@group-47BEDE733167-SegmentedRaftLogWorker]
> SegmentedRaftLogWorker: 1@group-47BEDE733167-SegmentedRaftLogWorker: Rolled
> log segment from
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/current/log_inprogress_34783744
> to
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/current/log_34783744-34795893
> 24/08/11 11:52:41,160 ERROR [1@group-47BEDE733167-StateMachineUpdater]
> StateMachineUpdater: 1@group-47BEDE733167-StateMachineUpdater caught a
> Throwable.
> java.lang.IllegalStateException: 1: Failed updateLastAppliedTermIndex: newTI
> = (t:59, i:34670810) < oldTI = (t:59, i:34795893)
> 24/08/11 11:52:41,161 INFO [1@group-47BEDE733167-StateMachineUpdater]
> RaftServer$Division: 1@group-47BEDE733167: shutdown
> 24/08/11 11:52:41,161 INFO [1@group-47BEDE733167-StateMachineUpdater]
> JmxRegister: Successfully un-registered JMX Bean with object name
> Ratis:service=RaftServer,group=group-47BEDE733167,id=1
> 24/08/11 11:52:41,161 INFO [1@group-47BEDE733167-StateMachineUpdater]
> RoleInfo: 1: shutdown 1@group-47BEDE733167-FollowerState
> 24/08/11 11:52:41,161 INFO [1@group-47BEDE733167-FollowerState]
> FollowerState: 1@group-47BEDE733167-FollowerState was interrupted
> 24/08/11 11:52:41,161 INFO [1@group-47BEDE733167-StateMachineUpdater]
> RaftServer$Division: 1@group-47BEDE733167: closes. applyIndex: 34670810
> 24/08/11 11:52:42,340 INFO [1@group-47BEDE733167-StateMachineUpdater]
> SegmentedRaftLogWorker: 1@group-47BEDE733167-SegmentedRaftLogWorker close()
> 24/08/11 11:52:48,170 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: receive installSnapshot:
> 3->1#0-t59,chunk:7179265b-d007-4835-9b5f-fa9e4d853b72,0
> 24/08/11 11:52:48,170 ERROR [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: installSnapshot failed
> org.apache.ratis.protocol.exceptions.ServerNotReadyException:
> 1@group-47BEDE733167 is not in [STARTING, RUNNING]: current state is CLOSED
> 24/08/11 11:52:58,171 INFO [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: receive installSnapshot:
> 3->1#0-t59,chunk:7f56f35f-20f3-4b42-bdb6-c2d52db646fc,0
> 24/08/11 11:52:58,171 ERROR [nioEventLoopGroup-3-3]
> SnapshotInstallationHandler: 1@group-47BEDE733167: installSnapshot failed
> org.apache.ratis.protocol.exceptions.ServerNotReadyException:
> 1@group-47BEDE733167 is not in [STARTING, RUNNING]: current state is CLOSED
> *(repeat 'receive installSnapshot and installSnapshot failed' for serval
> hours until I restarted the server)*
> *Here is what I found in the leader's log*
> 24/08/11 09:03:10,130 WARN
> [3@group-47BEDE733167->1-LogAppenderDefault-LogAppenderDaemon] LogAppender:
> 3@group-47BEDE733167->1-LogAppenderDefault: Failed to appendEntries
> (retry=1): org.apache.ratis.protocol.exceptions.TimeoutIOException
> 24/08/11 09:03:13,714 INFO
> [3@group-47BEDE733167->1-LogAppenderDefault-LogAppenderDaemon] FollowerInfo:
> 3@group-47BEDE733167->1: decreaseNextIndex nextIndex: updateUnconditionally
> 34795876 -> 34795875
> 24/08/11 09:03:13,715 INFO
> [3@group-47BEDE733167->1-LogAppenderDefault-LogAppenderDaemon] FollowerInfo:
> 3@group-47BEDE733167->1: decreaseNextIndex nextIndex: updateUnconditionally
> 34795875 -> 34795874
> *I guess when the leader called appendEntries for the first time, the
> follower had been executed successfully, but the leader did not receive the
> follower's response and times out. When it resent, it found that it could not
> match the change and started to decreaseNextIndex.*
> *Sometimes it can be fixed automatically by rolling segment log, but not
> always.*
> 24/08/12 11:47:53,351 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 2@group-47BEDE733167: Failed appendEntries as the first entry (index
> 35049128) already exists (snapshotIndex: 35070063, commitIndex: 35259248)
> 24/08/12 11:47:53,351 INFO [nioEventLoopGroup-3-3] RaftServer$Division:
> 2@group-47BEDE733167: inconsistency entries.
> Reply:3<-2#3583083:FAIL-t59,INCONSISTENCY,nextIndex=35259249,followerCommit=35259248,matchIndex=-1
> 24/08/12 11:47:55,132 INFO [nioEventLoopGroup-3-3] SegmentedRaftLogWorker:
> 2@group-47BEDE733167-SegmentedRaftLogWorker: Rolling segment
> log-35250411_35261308 to index:35261308
> 24/08/12 11:54:46,402 INFO [2@group-47BEDE733167-StateMachineUpdater]
> StateMachine: Taking a snapshot to file
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/tmp/raft_snapshot_1723434886330_4407392949522239377.dat.
> 24/08/12 11:54:46,403 INFO [2@group-47BEDE733167-StateMachineUpdater]
> StateMachine: Saving digest 272e2c87a8e62785588ab383c0b8c290 for snapshot
> file
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/sm/snapshot.59_35270066.
> 24/08/12 11:54:46,458 INFO [2@group-47BEDE733167-StateMachineUpdater]
> StateMachine: Renaming a snapshot file
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/tmp/raft_snapshot_1723434886330_4407392949522239377.dat
> to
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/sm/snapshot.59_35270066.
> 24/08/12 11:54:46,487 INFO [2@group-47BEDE733167-StateMachineUpdater]
> SimpleStateMachineStorage: Deleting old snapshot at
> /data0/celeborn/ha_ratis/c5196f6d-2c34-3ed3-8b8a-47bede733167/sm/snapshot.59_34670063
> 24/08/12 11:54:46,530 INFO [2@group-47BEDE733167-StateMachineUpdater]
> StateMachineUpdater: 2@group-47BEDE733167-StateMachineUpdater: Took a
> snapshot at index 35270066
> 24/08/12 11:54:46,530 INFO [2@group-47BEDE733167-StateMachineUpdater]
> StateMachineUpdater: 2@group-47BEDE733167-StateMachineUpdater: snapshotIndex:
> updateIncreasingly 35070063 -> 35270066
> 24/08/12 11:57:16,592 INFO [nioEventLoopGroup-3-3] SegmentedRaftLogWorker:
> 2@group-47BEDE733167-SegmentedRaftLogWorker: Rolling segment
> log-35261309_35271592 to index:35271592
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
