Preferred Leader leads to node unavailability problem #85

Git-Yang · 2021-07-26T02:57:37Z

The initial state of the broker group
n0 is master, preferredLeader
n1 and n2 is slave

The status after the re-election is as follows
n0 and n2 is slave
n1 is master

Problem Description
n0 node cannot synchronize data.

If the cluster restarts, the brokerId is always -1.

Problem Analysis
When the preferredLeader is triggered to re-initiate the election, if the ldeger entry index lags behind the leader node, the vote fails.
As the term increases by 1, the node is always larger than the other node's term and cannot be re-elected as a follower. Therefore, the preferredLeader will always be in the candidate state, resulting in the node being unavailable.

The log of the n0 node is as follows

The log of the n1 node is as follows

Git-Yang · 2021-07-26T03:03:49Z

Optimization ideas
The first optimization scheme: When the leader receives the heartbeat response, if the response term is greater than the current term, it re-enters the Candidate to initiate the next round of voting.
Shortcomings: May trigger multiple re-elections.

Git-Yang · 2021-07-28T07:03:10Z

@vongosling Can you help me review this revision?

Git-Yang · 2021-07-28T07:08:21Z

Optimization ideas
The second optimization scheme:

Mark the unavailable state of the node in the voting phase.
When receiving the heartbeat of the leader node, if the node status is unavailable, try to recover.

maixiaohai · 2021-07-29T16:56:34Z

@RongtongJin this change may not a good choice, can you help to review it. This problem will cause the unavailable of node of broker group.

Cczzzz · 2021-09-29T07:38:20Z

I think ,if preferred leader is too much behind。Should be downgraded follower

Git-Yang · 2021-09-29T08:23:39Z

I think ,if preferred leader is too much behind。Should be downgraded follower

After downgrading to follower, the voting term is still larger than other nodes. Therefore, the term will be rolled back first and then the node will be downgraded to follower.

Cczzzz · 2021-10-22T11:20:33Z

I did the test before，Seems to be in line with expectations. this is my log。
How do i reproduce your situation。

leader = > FOLLOWER

2021-10-20 10:42:09 INFO DLedgerServer-ScheduledExecutor - transferee fall behind index : 274935
2021-10-20 10:42:10 INFO QuorumAckChecker-n1 - [n1][LEADER] term=4 ledgerBegin=0 ledgerEnd=27204416 committed=27204405 watermarks={4:{"n0":26989087,"n1":27204416,"n2":27204405}}
2021-10-20 10:42:10 INFO DLedgerServer-ScheduledExecutor - transferee fall behind index : 189040
2021-10-20 10:42:11 INFO DLedgerServer-ScheduledExecutor - transferee fall behind index : 93585
2021-10-20 10:42:12 INFO DLedgerServer-ScheduledExecutor - transferee fall behind index : 0
2021-10-20 10:42:12 INFO DLedgerServer-ScheduledExecutor - handleLeadershipTransfer: LeadershipTransferRequest{transferId='null', transfereeId='n0', takeLeadershipLedgerIndex=0, group='null', remoteId='null', localId='null', code=200, leaderId='null', term=4}
2021-10-20 10:42:12 ERROR SendMessageThread_5 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_35 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_3 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_41 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_43 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_25 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_35 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 ERROR SendMessageThread_44 - [n1][HandleAppend] failed
io.openmessaging.storage.dledger.exception.DLedgerException: [code=506,name=LEADER_TRANSFERRING,desc=]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:32) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.utils.PreConditions.check(PreConditions.java:25) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at io.openmessaging.storage.dledger.DLedgerServer.handleAppend(DLedgerServer.java:163) ~[dledger-0.2.3-SNAPSHOT.jar:na]
at org.apache.rocketmq.store.dledger.DLedgerCommitLog.asyncPutMessage(DLedgerCommitLog.java:446) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.store.DefaultMessageStore.asyncPutMessage(DefaultMessageStore.java:431) ~[rocketmq-store-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncSendMessage(SendMessageProcessor.java:314) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:101) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.broker.processor.SendMessageProcessor.asyncProcessRequest(SendMessageProcessor.java:82) ~[rocketmq-broker-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:225) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at org.apache.rocketmq.remoting.netty.RequestTask.run(RequestTask.java:80) ~[rocketmq-remoting-4.9.1.jar:4.9.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2021-10-20 10:42:12 INFO NettyServerPublicExecutor_2 - [n1] [ChangeRoleToCandidate] from term: 5 and currTerm: 4
2021-10-20 10:42:12 INFO StateMaintainer - n1_[INCREASE_TERM] from 4 to 5
2021-10-20 10:42:12 INFO DLedgerServer-ScheduledExecutor - transfer finished. request=LeadershipTransferRequest{transferId='null', transfereeId='n0', takeLeadershipLedgerIndex=0, group='null', remoteId='null', localId='null', code=200, leaderId='null', term=4},response=LeadershipTransferResponse{group='null', remoteId='null', localId='null', code=200, leaderId='null', term=5},cost=63ms
2021-10-20 10:42:12 INFO NettyServerPublicExecutor_1 - [n1][ChangeRoleToFollower] from term: 5 leaderId: n0 and currTerm:5
2021-10-20 10:42:12 WARN EntryHandler-n1 - [MONITOR]Skip update committed index for new=27205821 < old=27205824 or new=27205821 < beginIndex=0
2021-10-20 10:42:13 INFO QuorumAckChecker-n1 - [n1][FOLLOWER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={4:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:16 INFO QuorumAckChecker-n1 - [n1][FOLLOWER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={4:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:19 INFO QuorumAckChecker-n1 - [n1][FOLLOWER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={4:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:22 INFO QuorumAckChecker-n1 - [n1][FOLLOWER] term=5 ledgerBegin=0 ledgerEnd=27205834 committed=27205834 watermarks={4:{"n0":27205824,"n1":27205824,"n2":27205824}}

FOLLOWER => leader

2021-10-20 10:41:51 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26559198 committed=26559198 watermarks={}
2021-10-20 10:41:54 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26619089 committed=26619089 watermarks={}
2021-10-20 10:41:57 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26678549 committed=26678549 watermarks={}
2021-10-20 10:42:00 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26737289 committed=26737289 watermarks={}
2021-10-20 10:42:03 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26797271 committed=26797271 watermarks={}
2021-10-20 10:42:06 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26857418 committed=26857418 watermarks={}
2021-10-20 10:42:09 INFO QuorumAckChecker-n0 - [n0][FOLLOWER] term=4 ledgerBegin=0 ledgerEnd=26949290 committed=26949290 watermarks={}
2021-10-20 10:42:12 INFO NettyServerPublicExecutor_1 - [n0] [ChangeRoleToCandidate] from term: 5 and currTerm: 4
2021-10-20 10:42:12 INFO StateMaintainer - n0_[INCREASE_TERM] from 4 to 5
2021-10-20 10:42:12 INFO StateMaintainer - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n0","term":5,"voteResult":"ACCEPT"}
2021-10-20 10:42:12 INFO NettyClientPublicExecutor_7 - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n1","term":4,"voteResult":"REJECT_TERM_NOT_READY"}
2021-10-20 10:42:12 INFO StateMaintainer - [n0] [PARSE_VOTE_RESULT] cost=4 term=5 memberNum=3 allNum=2 acceptedNum=1 notReadyTermNum=1 biggerLedgerNum=0 alreadyHasLeader=false maxTerm=5 result=REVOTE_IMMEDIATELY
2021-10-20 10:42:12 INFO NettyClientPublicExecutor_8 - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n2","term":4,"voteResult":"REJECT_TERM_NOT_READY"}
2021-10-20 10:42:12 INFO StateMaintainer - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n0","term":5,"voteResult":"ACCEPT"}
2021-10-20 10:42:12 INFO NettyClientPublicExecutor_1 - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n1","term":5,"voteResult":"ACCEPT"}
2021-10-20 10:42:12 INFO StateMaintainer - [n0] [PARSE_VOTE_RESULT] cost=2 term=5 memberNum=3 allNum=2 acceptedNum=2 notReadyTermNum=0 biggerLedgerNum=0 alreadyHasLeader=false maxTerm=5 result=PASSED
2021-10-20 10:42:12 INFO StateMaintainer - [n0] [VOTE_RESULT] has been elected to be the leader in term 5
2021-10-20 10:42:12 INFO NettyClientPublicExecutor_2 - [n0][GetVoteResponse] {"code":200,"group":"broker-a","leaderId":"n0","remoteId":"n2","term":5,"voteResult":"ACCEPT"}
2021-10-20 10:42:12 INFO StateMaintainer - TakeLeadershipTask finished. request=LeadershipTransferRequest{transferId='n1', transfereeId='n0', takeLeadershipLedgerIndex=27205824, group='broker-a', remoteId='n0', localId='n1', code=200, leaderId='n1', term=4}, response=LeadershipTransferResponse{group='null', remoteId='null', localId='null', code=200, leaderId='null', term=5}, term=5, role=LEADER
2021-10-20 10:42:12 INFO StateMaintainer - [n0] [ChangeRoleToLeader] from term: 5 and currTerm: 5
2021-10-20 10:42:12 INFO QuorumAckChecker-n0 - Initialize the pending append map in QuorumAckChecker for term=5
2021-10-20 10:42:12 INFO QuorumAckChecker-n0 - Initialize the watermark in QuorumAckChecker for term=5
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n1 - [Push-n1]Change state from COMPARE to COMPARE at -1
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n1 - [Push-n1][DoCompare] compareIndex=-1 means start to compare
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n2 - [Push-n2]Change state from COMPARE to COMPARE at -1
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n2 - [Push-n2][DoCompare] compareIndex=-1 means start to compare
2021-10-20 10:42:12 INFO FutureExecutor_3 - LEADERSHIP_TRANSFER FINISHED. Request=RemotingCommand [code=51005, language=JAVA, version=395, opaque=193491726, flag(B)=0, remark=null, extFields=null, serializeTypeCurrentRPC=JSON], response=LeadershipTransferResponse{group='null', remoteId='null', localId='null', code=200, leaderId='null', term=5}, cost=57ms
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n1 - [Push-n1]Change state from COMPARE to APPEND at 27205824
2021-10-20 10:42:12 INFO EntryDispatcher-n0-n2 - [Push-n2]Change state from COMPARE to APPEND at 27205824
2021-10-20 10:42:12 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={5:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:15 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={5:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:18 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205824 committed=27205824 watermarks={5:{"n0":27205824,"n1":27205824,"n2":27205824}}
2021-10-20 10:42:21 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205834 committed=27205834 watermarks={5:{"n0":27205834,"n1":27205834,"n2":27205834}}
2021-10-20 10:42:24 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205834 committed=27205834 watermarks={5:{"n0":27205834,"n1":27205834,"n2":27205834}}
2021-10-20 10:42:27 INFO QuorumAckChecker-n0 - [n0][LEADER] term=5 ledgerBegin=0 ledgerEnd=27205844 committed=27205844 watermarks={5:{"n0":27205844,"n1":27205844,"n2":27205844}}

Cczzzz · 2021-10-22T11:23:40Z

when preferredLeader too much behind ，
leader will log ： transferee fall behind index
preferredLeader Will not send votes and Increase one's tenure

Git-Yang · 2021-10-26T02:13:40Z

when preferredLeader too much behind ， leader will log ： transferee fall behind index preferredLeader Will not send votes and Increase one's tenure

The following is an example of triggering an exception:
For example, the broker group contains three nodes n0 n1 n2, where n0 is the preferred Leader, the current state n0 is the follower, n1 is the leader, n2 is the follower, and the voting round term=1.

Current status
- preferredLeaderId=n0
- n0: follower, term=1, pledgerEndIndex=95
- n1: leader, term=1, pledgerEndIndex=100
- n2: follower, term=1, pledgerEndIndex=95

First:
When checkPreferredLeader occurs, the status of n0 changes to Candidate, term=2 and the next round of voting is initiated. At this time, n0 cannot synchronize data. (Candidate is not synchronizing data)

Trigger checkPreferredLeader
- n0: candidate, term=2, pledgerEndIndex=100
- n1: leader, term=1, pledgerEndIndex=120
- n2: follower, term=1, pledgerEndIndex=110
  The current status of n0 is Candidate, and a vote is initiated to n1 and n2 at this time. Since ledgerEndIndex in node n0 is smaller than n0 n2, voting fails and REJECT_SMALL_LEDGER_END_INDEX is returned.
n0 vote on n1 and n2
- n0: candidate, term=2, ACCEPT
- n1: leader, term=1, REJECT_SMALL_LEDGER_END_INDEX
- n2: follower, term=1, REJECT_SMALL_LEDGER_END_INDEX

Second:
n1 sends a heartbeat to n0 n2, n2 returns SUCCESS, and n0 returns EXPIRED_TERM. At this time, according to the above logic n0, more than half of the transmission is successful (the initial value is 1, which means that the heartbeat is sent to itself successfully), then n0 is still the leader.
Since n0 is in the Candidate state, n0 cannot synchronize the leader's data, resulting in ledgerEndIndex in n0 to always be less than n1 and n2.

n1 sends heartbeats to n0 and n2
- n0: candidate, term=2, EXPIRED_TERM
- n1: leader, term=1, SUCCESS
- n2: follower, term=1, SUCCESS
Node status after the above checkPreferredLeader, voting, heartbeat and other operations
- n0: candidate, term=2, pledgerEndIndex=100
- n1: leader, term=1, pledgerEndIndex=2000
- n2: follower, term=1, pledgerEndIndex=1990

In the above scenario, n0 is always in the Candidate state, and voting is continuously initiated, resulting in node n0 being unavailable.

如下为一个触发异常的例子：
比如broker组中包含三个节点n0 n1 n2，其中 n0 为 preferredLeader，当前状态 n0 为follower，n1 为leader，n2 为follower，投票轮次 term=1。

当前状态
- preferredLeaderId=n0
- n0：follower，term=1，dledgerEndIndex=95
- n1：leader，term=1，dledgerEndIndex=100
- n2：follower，term=1，dledgerEndIndex=95

第一步：
当发生 checkPreferredLeader 时，n0 状态变为Candidate，term=2并发起下一轮投票，此时n0无法同步数据。（Candidate不在同步数据）

触发 checkPreferredLeader
- n0：candidate，term=2，dledgerEndIndex=100
- n1：leader，term=1，dledgerEndIndex=120
- n2：follower，term=1，dledgerEndIndex=110
  n0 当前状态为 Candidate，此时向 n1 n2 发起投票。由于 n0 节点中 ledgerEndIndex 比 n0 n2 小，因此投票失败，返回REJECT_SMALL_LEDGER_END_INDEX。
n0 向 n1 和 n2 发起投票
- n0：candidate，term=2，ACCEPT
- n1：leader，term=1，REJECT_SMALL_LEDGER_END_INDEX
- n2：follower，term=1，REJECT_SMALL_LEDGER_END_INDEX

第二步：
n1 向 n0 n2 发送心跳， n2 返回SUCCESS，n0 返回EXPIRED_TERM。此时按照上述逻辑n0中超过半数发送成功（初始为1，表示向自己发送心跳成功），则 n0 仍为 leader 。
由于 n0 处于 Candidate 状态，因此 n0 无法同步 leader 的数据，导致 n0 中 ledgerEndIndex 始终小于 n1 和 n2。

n1 向 n0 和 n2 发送心跳
- n0：candidate，term=2，EXPIRED_TERM
- n1：leader，term=1，SUCCESS
- n2：follower，term=1，SUCCESS
经过上述checkPreferredLeader、投票、心跳等操作后节点状态
- n0：candidate，term=2，dledgerEndIndex=100
- n1：leader，term=1，dledgerEndIndex=2000
- n2：follower，term=1，dledgerEndIndex=1990

在上述场景中，n0 始终为 Candidate状态，并不断发起投票，导致 n0 节点不可用。

Cczzzz · 2021-10-27T13:49:56Z

当preferredLeader落后太多时，leader会记录：受让者落后索引preferredLeader不会送票和增加任期

下面是一个触发异常的例子： 例如broker group包含三个节点n0 n1 n2，其中n0是首选Leader，当前状态n0是follower，n1是leader，n2是follower，投票轮期=1。

当前状态

首选领导者Id = n0

n0：追随者，任期=1，质押者EndIndex=95

n1：领导者，任期=1，承诺者EndIndex=100

n2：追随者，任期=1，质押者EndIndex=95

第一： 当checkPreferredLeader发生时，n0状态变为Candidate，term=2，开始下一轮投票。此时n0无法同步数据。（候选人未同步数据）

触发检查PreferredLeader

n0：候选人，任期=2，承诺者EndIndex=100

n1：领导者，任期=1，质押者EndIndex=120

n2：follower，term=1，worderEndIndex=110
n0当前状态为Candidate，此时对n1和n2发起投票。由于节点 n0 中的 ledgerEndIndex 小于 n0 n2，投票失败并返回 REJECT_SMALL_LEDGER_END_INDEX。

n0 对 n1 和 n2 投票

n0：候选人，任期=2，接受

n1：领导者，任期=1，REJECT_SMALL_LEDGER_END_INDEX

n2：追随者，term=1，REJECT_SMALL_LEDGER_END_INDEX

第二： n1 向 n0 n2 发送心跳，n2 返回 SUCCESS，n0 返回 EXPIRED_TERM。这时候按照上面的逻辑n0，传输成功了一半以上（初始值为1，表示心跳发送给自己成功），那么n0仍然是leader。由于n0处于Candidate状态，n0无法同步leader的数据，导致n0中的ledgerEndIndex始终小于n1和n2。

n1 向 n0 和 n2 发送心跳

n0：候选人，任期=2，EXPIRED_TERM

n1：领导者，任期=1，成功

n2：追随者，任期=1，成功

上面checkPreferredLeader、投票、心跳等操作后的节点状态

n0：候选人，任期=2，承诺者EndIndex=100

n1：领导者，任期=1，承诺者EndIndex=2000

n2：追随者，任期=1，质押者EndIndex=1990

上述场景中，n0始终处于Candidate状态，不断发起投票，导致节点n0不可用。

以下为一个触发异常的例子：比如broker组中包含三个节点n0 n1 n2，其中n0为preferredLeader，当前状态n0为follower，n1为leader，n2次为follower，投票轮term=1。

当前状态

首选领导者Id = n0

n0：follower，term=1，dledgerEndIndex=95

n1：leader，term=1，dledgerEndIndex=100

n2：follower，term=1，dledgerEndIndex=95

**** 早期**：**当发生checkPreferredLeader时，n0状态变为Candidate，term=2并发起无法投票，此时n0同步数据。（Candidate不在同步数据）

触发 checkPreferredLeader

n0：候选人，term=2，dledgerEndIndex=100

n1：leader，term=1，dledgerEndIndex=120

n2：follower，term=1，dledgerEndIndex=110
n0 当前状态为候选，此时向 n1 n2 发起投票。由于 n0 节点中 ledgerEndIndex 比 n0 n2 小，因此投票失败，返回REJECT_SMALL_LEDGER_END_INDEX。

n0 向 n1 和 n2 发起投票

n0：候选人，任期=2，接受

n1：leader，term=1，REJECT_SMALL_LEDGER_END_INDEX

n2：follower，term=1，REJECT_SMALL_LEDGER_END_INDEX

第二步： 。N1向N2 N0发送心跳，N2返回SUCCESS，N0返回EXPIRED_TERM此时按照上述逻辑N0中超过半数发送成功（初始为1，表示向自己发送心跳成功），则N0仍为领头羊由于n0等待候选状态，n0无法同步leader的数据，导致n中分类账EndIndex0因此总是小于n1和n2。

n1 向 n0 和 n2 发送心跳

n0：候选人，任期=2，EXPIRED_TERM

n1：领导者，任期=1，成功

n2：follower，term=1，成功

经过上述检查PreferredLeader、投票、心跳等操作后神经状态

n0：候选人，term=2，dledgerEndIndex=100

n1：leader，term=1，dledgerEndIndex=2000

n2：follower，term=1，dledgerEndIndex=1990

在上述场景中，n0 总是为候选状态，并不断发起投票，导致 n0 不能启动。

thanks，I will test it

Git-Yang · 2022-01-08T06:37:22Z

@RongtongJin Please help to review it, and I am very much looking forward to other better optimization methods that may be communicated together.

Signed-off-by: zhangyang21 <[email protected]>

RongtongJin · 2022-03-28T12:50:52Z

Merged

Git-Yang mentioned this issue Jul 26, 2021

[ISSUE 85] Repair preferred leader bug #86

Closed

RongtongJin added the bug Something isn't working label Sep 26, 2021

Git-Yang added a commit to Git-Yang/dledger that referenced this issue Jan 26, 2022

[ISSUE openmessaging#85] fix preferred leader bug

efaddd3

Signed-off-by: zhangyang21 <[email protected]>

Git-Yang mentioned this issue Jan 26, 2022

[ISSUE #85] fix preferred leader bug #106

Merged

Git-Yang added a commit to Git-Yang/dledger that referenced this issue Jan 26, 2022

[ISSUE openmessaging#85] fix preferred leader bug

081c54d

Signed-off-by: zhangyang21 <[email protected]>

Git-Yang added a commit to Git-Yang/dledger that referenced this issue Jan 26, 2022

[ISSUE openmessaging#85] fix preferred leader bug

8f5ec42

Signed-off-by: zhangyang21 <[email protected]>

Git-Yang added a commit to Git-Yang/dledger that referenced this issue Mar 22, 2022

[ISSUE openmessaging#85] fix preferred leader bug

5da316a

Signed-off-by: zhangyang21 <[email protected]>

RongtongJin pushed a commit that referenced this issue Mar 22, 2022

[ISSUE #85] fix preferred leader bug (#106)

bbaaec6

Signed-off-by: zhangyang21 <[email protected]>

RongtongJin closed this as completed Mar 28, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Preferred Leader leads to node unavailability problem #85

Preferred Leader leads to node unavailability problem #85

Git-Yang commented Jul 26, 2021

Git-Yang commented Jul 26, 2021

Git-Yang commented Jul 28, 2021

Git-Yang commented Jul 28, 2021

maixiaohai commented Jul 29, 2021

Cczzzz commented Sep 29, 2021

Git-Yang commented Sep 29, 2021

Cczzzz commented Oct 22, 2021

Cczzzz commented Oct 22, 2021

Git-Yang commented Oct 26, 2021

Cczzzz commented Oct 27, 2021

Git-Yang commented Jan 8, 2022

RongtongJin commented Mar 28, 2022

Preferred Leader leads to node unavailability problem #85

Preferred Leader leads to node unavailability problem #85

Comments

Git-Yang commented Jul 26, 2021

Git-Yang commented Jul 26, 2021

Git-Yang commented Jul 28, 2021

Git-Yang commented Jul 28, 2021

maixiaohai commented Jul 29, 2021

Cczzzz commented Sep 29, 2021

Git-Yang commented Sep 29, 2021

Cczzzz commented Oct 22, 2021

Cczzzz commented Oct 22, 2021

Git-Yang commented Oct 26, 2021

Cczzzz commented Oct 27, 2021

Git-Yang commented Jan 8, 2022

RongtongJin commented Mar 28, 2022