You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ratis.apache.org by "Mukul Kumar Singh (JIRA)" <ji...@apache.org> on 2018/08/24 09:32:00 UTC
[jira] [Created] (RATIS-304) Leader send incorrect entries to
follower after withholding election
Mukul Kumar Singh created RATIS-304:
---------------------------------------
Summary: Leader send incorrect entries to follower after withholding election
Key: RATIS-304
URL: https://issues.apache.org/jira/browse/RATIS-304
Project: Ratis
Issue Type: Bug
Components: server
Affects Versions: 0.3.0
Reporter: Mukul Kumar Singh
Fix For: 0.3.0
Leader send incorrect entries to follower after withholding election.
The following exception was seen using Ozone, where the leader send incorrect append entries to follower.
{code}
2018-08-20 07:54:06,200 INFO org.apache.ratis.server.storage.RaftLogWorker: Rolling segment:2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858-RaftLogWorker index to:20312
2018-08-20 07:54:07,800 INFO org.apache.ratis.server.impl.FollowerState: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes to CANDIDATE, lastRpcTime:1182, electionTimeout:990ms
2018-08-20 07:54:07,800 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes role from org.apache.ratis.server.impl.RoleInfo@6b1e0fb8 to CANDIDATE at term 14
for changeToCandidate
2018-08-20 07:54:07,801 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes role from org.apache.ratis.server.impl.RoleInfo@6b1e0fb8 to FOLLOWER at term 14
for changeToFollower
2018-08-20 07:54:21,712 INFO org.apache.ratis.server.impl.FollowerState: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes to CANDIDATE, lastRpcTime:2167, electionTimeout:976ms
2018-08-20 07:54:21,712 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes role from org.apache.ratis.server.impl.RoleInfo@6b1e0fb8 to CANDIDATE at term 14
for changeToCandidate
2018-08-20 07:54:21,715 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: change Leader from 2bf278ca-2dad-4029-a387-2faeb10adef5_9858 to null at term 14 for ini
tElection
2018-08-20 07:54:29,151 INFO org.apache.ratis.server.impl.LeaderElection: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: begin an election in Term 15
2018-08-20 07:54:30,735 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 changes role from org.apache.ratis.server.impl.RoleInfo@6b1e0fb8 to FOLLOWER at term 15
for changeToFollower
2018-08-20 07:54:30,740 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: change Leader from null to b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 at term 15 for app
endEntries
2018-08-20 07:54:30,741 INFO org.apache.ratis.server.impl.RaftServerImpl: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858-org.apache.ratis.server.impl.RoleInfo@6b1e0fb8: Withhold vote from candidate b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 with term 15. State: leader=b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858, term=15, lastRpcElapsed=0ms
2018-08-20 07:54:30,745 INFO org.apache.ratis.server.impl.LeaderElection: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: Election REJECTED; received 1 response(s) [2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858<-2
bf278ca-2dad-4029-a387-2faeb10adef5_9858#0:FAIL-t15] and 0 exception(s); 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858:t15, leader=b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858, voted=2e240240-0fac-4f93-8aa8-fa8f
74bf1810_9858, raftlog=[(t:14, i:20374)], conf=[b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858:172.26.32.231:9858, 2bf278ca-2dad-4029-a387-2faeb10adef5_9858:172.26.32.230:9858, 2e240240-0fac-4f93-8aa8-fa8f74bf
1810_9858:172.26.32.228:9858], old=null
2018-08-20 07:54:31,227 WARN org.apache.ratis.grpc.server.RaftServerProtocolService: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: Failed appendEntries b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858->2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858#1
java.lang.IllegalStateException: Unexpected Index: previous is (t:14, i:20374) but entries[0].getIndex()=0
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:60)
at org.apache.ratis.server.impl.RaftServerImpl.validateEntries(RaftServerImpl.java:786)
at org.apache.ratis.server.impl.RaftServerImpl.appendEntriesAsync(RaftServerImpl.java:859)
at org.apache.ratis.server.impl.RaftServerImpl.appendEntriesAsync(RaftServerImpl.java:824)
at org.apache.ratis.server.impl.RaftServerProxy.appendEntriesAsync(RaftServerProxy.java:247)
at org.apache.ratis.grpc.server.RaftServerProtocolService$1.onNext(RaftServerProtocolService.java:76)
at org.apache.ratis.grpc.server.RaftServerProtocolService$1.onNext(RaftServerProtocolService.java:66)
at org.apache.ratis.shaded.io.grpc.stub.ServerCalls$StreamingServerCallHandler$StreamingServerCallListener.onMessage(ServerCalls.java:248)
at org.apache.ratis.shaded.io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:252)
at org.apache.ratis.shaded.io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:629)
at org.apache.ratis.shaded.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at org.apache.ratis.shaded.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2018-08-20 07:54:33,260 WARN org.apache.ratis.grpc.server.RaftServerProtocolService: 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858: Failed appendEntries b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858->2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858#3
java.lang.IllegalStateException: Unexpected Index: entries[1].getIndex()=0 but entries[0].getIndex()=0
{code}
{code}
2018-08-20 11:54:29,174 INFO org.apache.ratis.grpc.server.RaftServerProtocolService: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: appendEntries completed
2018-08-20 11:54:30,182 INFO org.apache.ratis.server.impl.FollowerState: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 changes to CANDIDATE, lastRpcTime:1332, electionTimeout:860ms
2018-08-20 11:54:30,182 INFO org.apache.ratis.server.impl.RaftServerImpl: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 changes role from org.apache.ratis.server.impl.RoleInfo@465f9230 to CANDIDATE at term 14
for changeToCandidate
2018-08-20 11:54:30,185 INFO org.apache.ratis.server.impl.RaftServerImpl: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: change Leader from 2bf278ca-2dad-4029-a387-2faeb10adef5_9858 to null at term 14 for initElection
2018-08-20 11:54:30,199 INFO org.apache.ratis.server.impl.LeaderElection: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: begin an election in Term 15
2018-08-20 11:54:30,230 INFO org.apache.ratis.server.impl.LeaderElection: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: Election PASSED; received 1 response(s) [b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858<-2bf
278ca-2dad-4029-a387-2faeb10adef5_9858#0:OK-t15] and 0 exception(s); b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858:t15, leader=null, voted=b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858, raftlog=[(t:14, i:20488)],
conf=[b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858:172.26.32.231:9858, 2bf278ca-2dad-4029-a387-2faeb10adef5_9858:172.26.32.230:9858, 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858:172.26.32.228:9858], old=null
2018-08-20 11:54:30,230 INFO org.apache.ratis.server.impl.RaftServerImpl: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 changes role from org.apache.ratis.server.impl.RoleInfo@465f9230 to LEADER at term 15 for changeToLeader
2018-08-20 11:54:30,230 INFO org.apache.ratis.server.impl.RaftServerImpl: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: change Leader from null to b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858 at term 15 for becomeLeader
2018-08-20 11:54:30,246 INFO org.apache.ratis.conf.ConfUtils: raft.server.staging.catchup.gap = 1000 (default)
2018-08-20 11:54:30,246 INFO org.apache.ratis.conf.ConfUtils: raft.server.rpc.sleep.time = 25 ms (default)
2018-08-20 11:54:30,269 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.buffer.capacity = 134217728 (custom)
2018-08-20 11:54:30,270 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.batch.enabled = true (custom)
2018-08-20 11:54:30,270 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2018-08-20 11:54:30,273 INFO org.apache.ratis.conf.ConfUtils: raft.grpc.server.leader.outstanding.appends.max = 128 (default)
2018-08-20 11:54:30,273 INFO org.apache.ratis.conf.ConfUtils: raft.server.rpc.request.timeout = 3000 ms (custom)
2018-08-20 11:54:30,274 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.buffer.capacity = 134217728 (custom)
2018-08-20 11:54:30,274 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.batch.enabled = true (custom)
2018-08-20 11:54:30,274 INFO org.apache.ratis.conf.ConfUtils: raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2018-08-20 11:54:30,274 INFO org.apache.ratis.conf.ConfUtils: raft.grpc.server.leader.outstanding.appends.max = 128 (default)
2018-08-20 11:54:30,274 INFO org.apache.ratis.conf.ConfUtils: raft.server.rpc.request.timeout = 3000 ms (custom)
2018-08-20 11:54:30,277 INFO org.apache.ratis.server.storage.RaftLogWorker: Rolling segment:b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858-RaftLogWorker index to:20489
2018-08-20 11:54:30,733 INFO org.apache.ratis.server.impl.RaftServerImpl: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858-org.apache.ratis.server.impl.RoleInfo@465f9230: Withhold vote from candidate 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858 with term 15. State: leader=b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858, term=15, lastRpcElapsed=null
2018-08-20 11:54:31,230 WARN org.apache.ratis.server.impl.LogAppender: b6aaaf2c-2cbf-498f-995c-09cb2bb97cf4_9858: Failed appendEntries to 2e240240-0fac-4f93-8aa8-fa8f74bf1810_9858:172.26.32.228:9858
java.io.IOException: java.lang.IllegalStateException: Unexpected Index: previous is (t:14, i:20374) but entries[0].getIndex()=0
at org.apache.ratis.util.IOUtils.asIOException(IOUtils.java:49)
at org.apache.ratis.grpc.RaftGrpcUtil.tryUnwrapException(RaftGrpcUtil.java:81)
at org.apache.ratis.grpc.RaftGrpcUtil.unwrapThrowable(RaftGrpcUtil.java:58)
at org.apache.ratis.grpc.RaftGrpcUtil.warn(RaftGrpcUtil.java:129)
at org.apache.ratis.grpc.server.GRpcLogAppender$AppendLogResponseHandler.onError(GRpcLogAppender.java:241)
at org.apache.ratis.shaded.io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:419)
at org.apache.ratis.shaded.io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41)
at org.apache.ratis.shaded.io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:684)
at org.apache.ratis.shaded.io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41)
at org.apache.ratis.shaded.io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:391)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:475)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:557)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:478)
{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)