Uploaded image for project: 'Ratis'
  1. Ratis
  2. RATIS-2135

The leader keeps sending inconsistent entries repeatedly to followers.

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 3.0.1
    • 3.1.1, 3.2.0
    • gRPC
    • None

    Description

      We found in the leader log of ratis that the follower replied leader nextIndex = 645891323, and the leader also executed setNextIndex nextIndex: updateUnconditionally 645892117 -> 645891323, but this process was repeated continuously, causing the follower to become unavailable.

      The following is the log of the leader node:

       

      2024/08/06 00:00:00,094 [grpc-default-executor-210] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL
      2024/08/06 00:00:00,103 [grpc-default-executor-210] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-GrpcLogAppender: Follower failed (request=null, errorCount=206); keep nextIndex (645892117) unchanged and retry.
      2024/08/06 00:00:00,400 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=207, request=AppendEntriesRequest:cid=51646275,entriesCount=744,entries=(t:626, i:645892117)...(t:626, i:645892860)
      2024/08/06 00:00:00,400 [grpc-default-executor-160] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892861 -> 645891323
      2024/08/06 00:00:02,888 [grpc-default-executor-210] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=209, request=AppendEntriesRequest:cid=51646277,entriesCount=669,entries=(t:626, i:645892117)...(t:626, i:645892785)
      2024/08/06 00:00:02,888 [grpc-default-executor-210] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892786 -> 645891323
      2024/08/06 00:00:03,344 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=211, request=AppendEntriesRequest:cid=51646279,entriesCount=744,entries=(t:626, i:645892117)...(t:626, i:645892860)
      2024/08/06 00:00:03,344 [grpc-default-executor-160] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892861 -> 645891323
      2024/08/06 00:00:05,103 [timer1] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: Failed appendEntries (Repeated 4 times in the last 5.009s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL
      2024/08/06 00:00:05,104 [timer2] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-GrpcLogAppender: Follower failed (request=null, errorCount=212); keep nextIndex (645892117) unchanged and retry. (Repeated 4 times in the last 5.001s)
      2024/08/06 00:00:05,833 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=213, request=AppendEntriesRequest:cid=51646281,entriesCount=669,entries=(t:626, i:645892117)...(t:626, i:645892785)
      2024/08/06 00:00:05,833 [grpc-default-executor-160] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892786 -> 645891323
      2024/08/06 00:00:05,996 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL
      2024/08/06 00:00:05,996 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-GrpcLogAppender: Follower failed (request=null, errorCount=214); keep nextIndex (645892117) unchanged and retry.
      2024/08/06 00:00:10,792 [grpc-default-executor-210] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=215, request=AppendEntriesRequest:cid=51646283,entriesCount=0
      2024/08/06 00:00:10,792 [grpc-default-executor-210] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892117 -> 645891323
      2024/08/06 00:00:10,996 [timer5] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-GrpcLogAppender: Follower failed (request=null, errorCount=216); keep nextIndex (645892117) unchanged and retry. (Repeated 2 times in the last 5.000s)
      2024/08/06 00:00:10,996 [timer4] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: Failed appendEntries (Repeated 2 times in the last 5.000s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL
      2024/08/06 00:00:15,014 [grpc-default-executor-160] WARN org.apache.ratis.grpc.server.GrpcLogAppender: node2@group-EE11FFDD70A4->node1-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 645891323, errorCount=217, request=AppendEntriesRequest:cid=51646285,entriesCount=0
      2024/08/06 00:00:15,014 [grpc-default-executor-160] INFO org.apache.ratis.server.leader.FollowerInfo: node2@group-EE11FFDD70A4->node1: setNextIndex nextIndex: updateUnconditionally 645892117 -> 645891323

      Attachments

        Issue Links

          Activity

            People

              szetszwo Tsz-wo Sze
              z-bb guangbao zhao
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 0.5h
                  0.5h