You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-dev@hadoop.apache.org by "Mukul Kumar Singh (JIRA)" <ji...@apache.org> on 2018/03/22 08:21:00 UTC
[jira] [Created] (HDFS-13327) Ratis should handle failure
conditions where append request to followers can fail
Mukul Kumar Singh created HDFS-13327:
----------------------------------------
Summary: Ratis should handle failure conditions where append request to followers can fail
Key: HDFS-13327
URL: https://issues.apache.org/jira/browse/HDFS-13327
Project: Hadoop HDFS
Issue Type: Bug
Reporter: Mukul Kumar Singh
Assignee: Mukul Kumar Singh
This was observed on a 3 node ratis config with ozone, this was simulated using TestFreon unit test.
The problem is append to {{127.0.0.1_63765}} failed because the node ran out of memory.
A new leader is elected which tries to send the append requests to the same follower, but the request is out of order.
{code}
2018-03-21 22:05:01,495 INFO ratis.ContainerStateMachine (ContainerStateMachine.java:handleWriteChunk(207)) - adding index 185
2018-03-21 22:05:02,054 WARN impl.LogAppender (GRpcLogAppender.java:onError(226)) - 127.0.0.1_63790 got error when appending entries to 127.0.0.1_63765, exception: {}.
java.io.IOException: org.apache.ratis.shaded.io.grpc.StatusRuntimeException: INTERNAL: Java heap space
at org.apache.ratis.grpc.RaftGrpcUtil.unwrapException(RaftGrpcUtil.java:65)
at org.apache.ratis.grpc.RaftGrpcUtil.unwrapThrowable(RaftGrpcUtil.java:48)
at org.apache.ratis.grpc.server.GRpcLogAppender$AppendLogResponseHandler.onError(GRpcLogAppender.java:227)
at org.apache.ratis.shaded.io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:395)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:481)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:398)
at org.apache.ratis.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:513)
at org.apache.ratis.shaded.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
at org.apache.ratis.shaded.io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154)
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)
Caused by: org.apache.ratis.shaded.io.grpc.StatusRuntimeException: INTERNAL: Java heap space
at org.apache.ratis.shaded.io.grpc.Status.asRuntimeException(Status.java:545)
... 9 more
2018-03-21 22:05:02,088 INFO ratis.ContainerStateMachine (ContainerStateMachine.java:applyTransaction(263)) - removing index 185
^M 90.00% |███████████████████████████████████████████████████████████████████████████████████████████ | 18/20 Time: 0:01:282018-03-21 22:05:02,622 INFO impl.FollowerState (FollowerState.java:r
un(72)) - 127.0.0.1_63776 changes to CANDIDATE, lastRpcTime:534, electionTimeout:414ms
2018-03-21 22:05:02,622 INFO impl.RaftServerImpl (RaftServerImpl.java:setRole(159)) - 127.0.0.1_63776 changes role from FOLLOWER to CANDIDATE at term 31 for changeToCandidate
2018-03-21 22:05:02,622 INFO impl.FollowerState (FollowerState.java:run(72)) - 127.0.0.1_63765 changes to CANDIDATE, lastRpcTime:576, electionTimeout:411ms
2018-03-21 22:05:02,623 INFO impl.RaftServerImpl (RaftServerImpl.java:setRole(159)) - 127.0.0.1_63765 changes role from FOLLOWER to CANDIDATE at term 31 for changeToCandidate
2018-03-21 22:05:02,623 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63776: change Leader from 127.0.0.1_63790 to null at term 31 for initElection
2018-03-21 22:05:02,628 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63765: change Leader from 127.0.0.1_63790 to null at term 31 for initElection
2018-03-21 22:05:02,634 INFO impl.LeaderElection (LeaderElection.java:askForVotes(127)) - 127.0.0.1_63765: begin an election in Term 32
2018-03-21 22:05:02,634 INFO impl.LeaderElection (LeaderElection.java:askForVotes(127)) - 127.0.0.1_63776: begin an election in Term 32
2018-03-21 22:05:02,635 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63790: change Leader from 127.0.0.1_63790 to null at term 32 for updateCurrentTerm
2018-03-21 22:05:02,635 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63790: change Leader from 127.0.0.1_63790 to null at term 32 for updateCurrentTerm
2018-03-21 22:05:02,636 INFO impl.RaftServerImpl (RaftServerImpl.java:setRole(159)) - 127.0.0.1_63790 changes role from LEADER to FOLLOWER at term 32 for changeToFollower
2018-03-21 22:05:02,636 INFO impl.PendingRequests (PendingRequests.java:sendNotLeaderResponses(147)) - 127.0.0.1_63790 sends responses before shutting down PendingRequestsHandler
2018-03-21 22:05:02,637 INFO server.RaftServerProtocolService (RaftServerProtocolService.java:onCompleted(104)) - 127.0.0.1_63776: appendEntries completed
2018-03-21 22:05:02,640 INFO impl.LogAppender (GRpcLogAppender.java:onCompleted(254)) - 127.0.0.1_63790 stops appending log entries to follower 127.0.0.1_63776(next=186, match=185, attendVote=true, lastR
pcSendTime=86068ms, lastRpcResponseTime=86080ms)
2018-03-21 22:05:02,646 INFO impl.LeaderElection (LeaderElection.java:logAndReturn(46)) - 127.0.0.1_63776: Election PASSED; received 2 response(s) [127.0.0.1_63776<-127.0.0.1_63765#0:FAIL-t32, 127.0.0.1_
63776<-127.0.0.1_63790#0:OK-t32] and 0 exception(s); 127.0.0.1_63776:t32, leader=null, voted=127.0.0.1_63776, raftlog=[(t:31, i:185)], conf=[127.0.0.1_63765:127.0.0.1:63765, 127.0.0.1_63776:127.0.0.1:6377
6, 127.0.0.1_63790:127.0.0.1:63790], old=null
2018-03-21 22:05:02,647 INFO impl.RaftServerImpl (RaftServerImpl.java:setRole(159)) - 127.0.0.1_63776 changes role from CANDIDATE to LEADER at term 32 for changeToLeader
2018-03-21 22:05:02,647 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63776: change Leader from null to 127.0.0.1_63776 at term 32 for becomeLeader
2018-03-21 22:05:02,647 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.staging.catchup.gap = 1000 (default)
2018-03-21 22:05:02,647 INFO impl.LeaderElection (LeaderElection.java:logAndReturn(46)) - 127.0.0.1_63765: Election REJECTED; received 2 response(s) [127.0.0.1_63765<-127.0.0.1_63776#0:FAIL-t32, 127.0.0.1_63765<-127.0.0.1_63790#0:FAIL-t32] and 0 exception(s); 127.0.0.1_63765:t32, leader=null, voted=127.0.0.1_63765, raftlog=[(t:31, i:185)], conf=[127.0.0.1_63765:127.0.0.1:63765, 127.0.0.1_63776:127.0.0.1:63776, 127.0.0.1_63790:127.0.0.1:63790], old=null
2018-03-21 22:05:02,647 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.rpc.sleep.time = 25 ms (default)
2018-03-21 22:05:02,650 INFO impl.RaftServerImpl (RaftServerImpl.java:setRole(159)) - 127.0.0.1_63765 changes role from CANDIDATE to FOLLOWER at term 32 for changeToFollower
2018-03-21 22:05:02,650 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.buffer.capacity = 134217728 (custom)
2018-03-21 22:05:02,650 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.batch.enabled = true (custom)
2018-03-21 22:05:02,652 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2018-03-21 22:05:02,653 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.grpc.server.leader.outstanding.appends.max = 128 (default)
2018-03-21 22:05:02,653 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.buffer.capacity = 134217728 (custom)
2018-03-21 22:05:02,653 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.batch.enabled = true (custom)
2018-03-21 22:05:02,653 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2018-03-21 22:05:02,653 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.grpc.server.leader.outstanding.appends.max = 128 (default)
2018-03-21 22:05:02,654 INFO storage.RaftLogWorker (RaftLogWorker.java:rollLogSegment(256)) - Rolling segment:127.0.0.1_63776-RaftLogWorker index to:186
2018-03-21 22:05:02,673 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63765: change Leader from null to 127.0.0.1_63776 at term 32 for appendEntries
2018-03-21 22:05:02,673 INFO impl.RaftServerImpl (ServerState.java:setLeader(215)) - 127.0.0.1_63790: change Leader from null to 127.0.0.1_63776 at term 32 for appendEntries
2018-03-21 22:05:02,674 INFO storage.RaftLogWorker (RaftLogWorker.java:rollLogSegment(256)) - Rolling segment:127.0.0.1_63790-RaftLogWorker index to:186
2018-03-21 22:05:02,674 INFO storage.RaftLogWorker (RaftLogWorker.java:rollLogSegment(256)) - Rolling segment:127.0.0.1_63765-RaftLogWorker index to:186
2018-03-21 22:05:02,712 INFO server.RaftServerProtocolService (RaftServerProtocolService.java:onCompleted(104)) - 127.0.0.1_63765: appendEntries completed
2018-03-21 22:05:02,713 INFO impl.LogAppender (GRpcLogAppender.java:onCompleted(254)) - 127.0.0.1_63790 stops appending log entries to follower 127.0.0.1_63765(next=186, match=184, attendVote=true, lastRpcSendTime=86081ms, lastRpcResponseTime=86157ms)
Mar 21, 2018 10:05:02 PM org.apache.ratis.shaded.io.grpc.internal.ManagedChannelImpl maybeTerminateChannel
INFO: [ManagedChannelImpl@643d117e] Terminated
2018-03-21 22:05:03,016 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.grpc.flow.control.window = 1MB (=1048576) (default)
2018-03-21 22:05:03,017 INFO conf.ConfUtils (ConfUtils.java:logGet(41)) - raft.grpc.message.size.max = 33554432 (custom)
Mar 21, 2018 10:05:03 PM org.apache.ratis.shaded.io.grpc.internal.ManagedChannelImpl <init>
INFO: [ManagedChannelImpl@4a23944d] Created with target 127.0.0.1:63776
2018-03-21 22:05:03,479 INFO ratis.ContainerStateMachine (ContainerStateMachine.java:applyTransaction(263)) - removing index 185
2018-03-21 22:05:03,562 ERROR storage.RaftLogWorker (ExitUtils.java:terminate(86)) - Terminating with exit status 1: 127.0.0.1_63765-RaftLogWorker failed.
java.lang.IllegalStateException: lastWrittenIndex == 184, entry == term: 32
index: 186
noOp {
}
{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-dev-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-dev-help@hadoop.apache.org