[RATIS-608] GrpcLogAppender sets next Index erroneously when follower is not accesible.

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Duplicate
• Component/s: gRPC, server
• Labels: ozone
• Assignee: Unassigned
• Reporter: Mukul Kumar Singh
• Created: 01/Jul/19 13:27
• Updated: 23/Aug/23 20:05
• Resolved: 23/Aug/23 20:05

Description

GrpcLogAppender sets the next Index erroneously when the follower is not accessible.

2019-06-30 15:46:29,779 INFO  impl.RaftServerImpl (ServerState.java:setRaftConf(361)) - 4819fbc0-e361-4926-932c-842627c9ffaa:group-4122452CF032 set configuration 2171: [e89e0844-d98e-4b11-8ead-64a6d2f9e2b
0:192.168.0.2:63501, 4819fbc0-e361-4926-932c-842627c9ffaa:192.168.0.2:63513, 3956fe0f-e48d-4616-a867-993d92dc33fe:192.168.0.2:63525], old=null at 2171

2019-06-30 15:46:29,779 WARN  server.GrpcLogAppender (LogUtils.java:warn(136)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: Failed appendEntries1: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception 2:org.apache.ratis.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.0.2:63501

2019-06-30 15:46:29,780 INFO  segmented.SegmentedRaftLogWorker (SegmentedRaftLogWorker.java:execute(526)) - 4819fbc0-e361-4926-932c-842627c9ffaa-SegmentedRaftLogWorker:Storage Directory /Users/msingh/code/apache/ozone/github/git_oz1/hadoop-ozone/integration-test/target/test/data/MiniOzoneClusterImpl-28640af6-bc0a-4f80-bc2d-d6d7c2cb932f/datanode-3/data/ratis/a6a7f1ed-bbde-445c-814d-4122452cf032: Rolled log segment from /Users/msingh/code/apache/ozone/github/git_oz1/hadoop-ozone/integration-test/target/test/data/MiniOzoneClusterImpl-28640af6-bc0a-4f80-bc2d-d6d7c2cb932f/datanode-3/data/ratis/a6a7f1ed-bbde-445c-814d-4122452cf032/current/log_inprogress_0 to /Users/msingh/code/apache/ozone/github/git_oz1/hadoop-ozone/integration-test/target/test/data/MiniOzoneClusterImpl-28640af6-bc0a-4f80-bc2d-d6d7c2cb932f/datanode-3/data/ratis/a6a7f1ed-bbde-445c-814d-4122452cf032/current/log_0-2170

2019-06-30 15:46:29,780 INFO  impl.FollowerInfo (FollowerInfo.java:lambda$new$0(51)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: nextIndex: updateUnconditionally 2171 -> 1


2019-06-30 15:46:29,812 WARN  server.GrpcLogAppender (LogUtils.java:warn(136)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: Failed appendEntries1: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception 2:org.apache.ratis.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.0.2:63501

2019-06-30 15:46:29,812 INFO  impl.FollowerInfo (FollowerInfo.java:lambda$new$0(51)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: nextIndex: updateUnconditionally 2 -> 1
2019-06-30 15:46:30,091 INFO  container.ContainerReportHandler (AbstractContainerReportHandler.java:updateContainerState(176)) - Moving container #9 to CLOSED state, datanode 823473d3-96da-4854-8688-9db0117c54d8{ip: 192.168.0.2, host: 192.168.0.2, networkLocation: /default-rack, certSerialId: null} reported CLOSED replica.

2019-06-30 15:46:30,321 WARN  server.GrpcLogAppender (LogUtils.java:warn(136)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: Failed appendEntries1: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception 2:org.apache.ratis.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.0.2:63501

2019-06-30 15:46:30,322 INFO  impl.FollowerInfo (FollowerInfo.java:lambda$new$0(51)) - g:group-4122452CF0324819fbc0-e361-4926-932c-842627c9ffaa->e89e0844-d98e-4b11-8ead-64a6d2f9e2b0: nextIndex: updateUnconditionally 1 -> 0

Issue Links

• duplicates: RATIS-1074 GrpcLogAppender improperly decrease nextIndex to 1, which may trigger a installSnapshot request to follower.
• duplicates: RATIS-1835 NextIndex is updated to 0 when leader connecting a restarting follower
• is related to: RATIS-611 Add a test for InstallSnapshotNotification with follower restart