[
https://issues.apache.org/jira/browse/RATIS-2156?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17881897#comment-17881897
]
Ivan Andika edited comment on RATIS-2156 at 9/16/24 3:19 AM:
-------------------------------------------------------------
Looking at the logs, the DN encountered a lot of the gRPC calls are cancelled
Leader
{code:java}
2024-09-13 11:20:25,876 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:25,898 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466714 -> 275465958
2024-09-13 11:20:26,004 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466057 -> 275465974
2024-09-13 11:20:26,004 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,004 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465974 -> 275465958
2024-09-13 11:20:26,106 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,110 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465958
2024-09-13 11:20:26,206 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465974
2024-09-13 11:20:26,206 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,213 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465992 -> 275465958
2024-09-13 11:20:26,311 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,314 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466057 -> 275465958
2024-09-13 11:20:26,439 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466090 -> 275465974
2024-09-13 11:20:26,446 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,446 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465974 -> 275465958
2024-09-13 11:20:26,519 [grpc-default-executor-32773] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465974
2024-09-13 11:20:26,520 [grpc-default-executor-32773] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL{code}
Follower (The "installSnapshot onError" is misleading since before RATIS-1811
every onError is marked as "installSnapshot")
{code:java}
2024-09-13 11:20:25,837 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635249576-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:25,992
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:25,992
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257589:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:25,994 [grpc-default-executor-5632] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257589-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,103
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,103
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257594:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,109 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257594-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,205
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,205
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257600:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,206 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257600-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,310
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,311 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257612-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,439
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40038] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,439
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40038] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257619:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,440 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257619-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,519
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,519
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257630:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,520 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257630-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,611
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,611
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257636:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,614 [grpc-default-executor-5632] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257636-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,697
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,698
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257643:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,698 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257643-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,805
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,812
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257649:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,813 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257649-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled {code}
Related gRPC-java issues:
[https://github.com/grpc/grpc-java/issues/9131]
[https://github.com/grpc/grpc-java/issues/8856] (This suggests that the
maxInboundMessageSize might be too small, but might be unlikely since Ratis
default configuration is 64MB)
Under normal condition, the index lag should trigger notifyInstallSnapshot
which will automatically trigger pipeline closure. However, due to the above
issue, the notifyInstallSnapshot was not called and therefore required manual
pipeline closure operation. Need to find the reasons of the CANCELLED gRPC
logs. Any idea is appreciated.
was (Author: JIRAUSER298977):
Looking at the logs, the DN encountered a lot of the gRPC calls are cancelled
Leader
{code:java}
2024-09-13 11:20:25,876 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:25,898 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466714 -> 275465958
2024-09-13 11:20:26,004 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466057 -> 275465974
2024-09-13 11:20:26,004 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,004 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465974 -> 275465958
2024-09-13 11:20:26,106 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,110 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465958
2024-09-13 11:20:26,206 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465974
2024-09-13 11:20:26,206 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,213 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465992 -> 275465958
2024-09-13 11:20:26,311 [grpc-default-executor-32790] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,314 [grpc-default-executor-32790] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466057 -> 275465958
2024-09-13 11:20:26,439 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466090 -> 275465974
2024-09-13 11:20:26,446 [grpc-default-executor-32783] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL
2024-09-13 11:20:26,446 [grpc-default-executor-32783] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275465974 -> 275465958
2024-09-13 11:20:26,519 [grpc-default-executor-32773] INFO
org.apache.ratis.server.leader.FollowerInfo:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607:
nextIndex: updateUnconditionally 275466037 -> 275465974
2024-09-13 11:20:26,520 [grpc-default-executor-32773] WARN
org.apache.ratis.grpc.server.GrpcLogAppender:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc@group-38F8784D0C1B->2d711272-c6fb-449c-8759-f42fbbfb0607-AppendLogResponseHandler:
Failed appendEntries:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED:
RST_STREAM closed stream. HTTP/2 error code: CANCEL{code}
Follower
{code:java}
2024-09-13 11:20:25,837 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635249576-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:25,992
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:25,992
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257589:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:25,994 [grpc-default-executor-5632] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257589-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,103
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,103
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40036] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257594:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,109 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257594-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,205
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,205
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257600:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,206 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257600-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,310
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,311 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257612-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,439
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40038] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,439
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40038] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257619:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,440 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257619-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,519
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,519
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257630:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,520 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257630-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,611
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,611
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257636:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,614 [grpc-default-executor-5632] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257636-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,697
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,698
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40049] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257643:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,698 [grpc-default-executor-5638] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257643-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled
2024-09-13 11:20:26,805
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: Failed appendEntries
as the first entry (index 275465958) already exists (snapshotIndex: -1,
commitIndex: 275465973)
2024-09-13 11:20:26,812
[2d711272-c6fb-449c-8759-f42fbbfb0607-server-thread40059] INFO
org.apache.ratis.server.RaftServer$Division:
2d711272-c6fb-449c-8759-f42fbbfb0607@group-38F8784D0C1B: inconsistency entries.
Reply:4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc<-2d711272-c6fb-449c-8759-f42fbbfb0607#635257649:FAIL-t5,INCONSISTENCY,nextIndex=275465974,followerCommit=275465973,matchIndex=-1
2024-09-13 11:20:26,813 [grpc-default-executor-5633] WARN
org.apache.ratis.grpc.server.GrpcServerProtocolService:
2d711272-c6fb-449c-8759-f42fbbfb0607: installSnapshot onError, lastRequest:
4a23d1e8-d526-4a4d-8ed1-13ffbab3a5cc->2d711272-c6fb-449c-8759-f42fbbfb0607#635257649-t5,previous=(t:5,
i:275465957),leaderCommit=275465973,initializing? true,entries: size=16,
first=(t:5, i:275465958), STATEMACHINELOGENTRY, 42288156@client-AE31E320960E:
org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: client
cancelled {code}
Related gRPC-java issues:
[https://github.com/grpc/grpc-java/issues/9131]
[https://github.com/grpc/grpc-java/issues/8856] (This suggests that the
maxInboundMessageSize might be too small, but might be unlikely since Ratis
default configuration is 64MB)
Under normal condition, the index lag should trigger notifyInstallSnapshot
which will automatically trigger pipeline closure. However, due to the above
issue, the notifyInstallSnapshot was not called and therefore required manual
pipeline closure operation. Need to find the reasons of the CANCELLED gRPC
logs. Any idea is appreciated.
> Notify follower slowness based on the log index
> -----------------------------------------------
>
> Key: RATIS-2156
> URL: https://issues.apache.org/jira/browse/RATIS-2156
> Project: Ratis
> Issue Type: Improvement
> Components: Leader
> Reporter: Ivan Andika
> Assignee: Ivan Andika
> Priority: Major
> Attachments: image-2024-09-13-18-54-04-203.png
>
>
> Currently the StateMachine.LeaderEventApi#notifyFollowerSlowness is based on
> raft.server.rpc.slowness.timeout, we saw that sometimes there are some cases
> where the rpc rtt between the leader and follower does not exceed the
> timeout, the difference of the log index between the leader and follower
> keeps increasing, i.e. the slow follower cannot catch up.
> In Ozone, this causes most watch requests with ALL_COMMITTED replication to
> timeout, causing increased latency of writes. It is better to close the
> pipeline if the slow follower cannot catch up.
> !image-2024-09-13-18-54-04-203.png|width=1408,height=244!
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
