use RatisConsensus.addPeer for a DataRegion , it does not works

Open BanDuWuZi opened this issue 3 years ago • 11 comments

Describe the bug use RatisConsensus.addPeer to migrate data/schema region, but it does not works

To Reproduce Steps to reproduce the behavior:

insert data to device SET STORAGE GROUP TO root.ln; CREATE TIMESERIES root.ln.wf01.wt01.status WITH DATATYPE=BOOLEAN, ENCODING=PLAIN; CREATE TIMESERIES root.ln.wf01.wt01.temperature WITH DATATYPE=FLOAT, ENCODING=RLE; INSERT INTO root.ln.wf01.wt01(timestamp,status) values(100,true); INSERT INTO root.ln.wf01.wt01(timestamp,status,temperature) values(200,false,20.71);
the data region RG1 is on Node1 and Node2.
call RatisConsensus.addPeer at Node1 to add a new peer(Node3) for RG1.
it not woks, and repeat a same log info in Node1:

repeat log info in new peer Node(Node3) : 2022-06-09 10:30:40,712 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:31:04,712 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:31:28,713 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:31:52,714 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:32:16,714 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:32:40,715 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:33:04,719 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:33:28,717 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY 2022-06-09 10:33:52,719 [grpc-default-executor-5] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.74-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.128-40010->192.168.42.74-40010#1-t2,previous=(t:0, i:0),leaderCommit=6,initializing? false,entries: size=7, first=(t:1, i:0), CONFIGURATIONENTRY

Jun 09 '22 03:06 BanDuWuZi

Node1 IP : 192.168.42.91 new peer (Node3) IP: 192.168.42.74

Jun 09 '22 03:06 BanDuWuZi

我在新的peer上调用addConsensusGroup后，然后再老peer节点执行addPeer和removePeer两个接口完成region迁移。可以成功，但有个新问题：例如：我要迁移Node1上的7个region，前几个成功了，中间的DataRegion[3] addPeer时卡主了 1.1 下面是Node1上的日志 InternalServiceImpl:481 - succeed to add new peer TEndPoint(ip:192.168.42.74, port:40010) for the region: SchemaRegion[6] InternalServiceImpl:502 - succeed to remove node TEndPoint(ip:192.168.42.91, port:40010) from the region consensus group: SchemaRegion[6] InternalServiceImpl:468 - start to add new peer TEndPoint(ip:192.168.42.74, port:40010) for the region: DataRegion[3] 打了开始，一直没结束 1.2 Node1的堆栈：

Jun 09 '22 08:06 BanDuWuZi

新peer（192.168.42.74）上的堆栈

Jun 09 '22 08:06 BanDuWuZi

根据讨论修改了addConsensusGroup的用法（添加所有peers）后，region迁移可以正常进行，但又有新问题。在NodeA上，移除NodeA上的所有region，会出现调用removePeer后，没结束，看日志，最后一行打了 JvmPauseMonitor-192.168.42.91-40010: Stopped 2022-06-09 21:19:04,991 [pool-1-IoTDB-InternalServiceRPC-Client-5] INFO o.a.i.d.s.t.i.InternalServiceImpl:486 - start to remove old peer TEndPoint(ip:192.168.42.91, port:40010) for the region: SchemaRegion[0] 2022-06-09 21:19:04,996 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.91-40010@group-000200000000: set configuration 15: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,001 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.91-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.74-40010->192.168.42.91-40010#18-t2,previous=(t:2, i:14),leaderCommit=14,initializing? true,entries: size=1, first=(t:2, i:15), CONFIGURATIONENTRY 2022-06-09 21:19:13,249 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,461 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,893 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,104 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,426 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,637 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,182 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] ......... 2022-06-09 21:19:20,903 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:246 - 192.168.42.91-40010@group-000200000000-SegmentedRaftLogWorker close() 2022-06-09 21:19:20,904 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.g.s.GrpcService:269 - 192.168.42.91-40010: shutdown server with port 40010 now 2022-06-09 21:19:20,913 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.g.s.GrpcService:278 - 192.168.42.91-40010: shutdown server with port 40010 successfully 2022-06-09 21:19:20,913 [org.apache.ratis.util.JvmPauseMonitor$$Lambda$142/307605969@464649c] INFO o.a.r.u.JvmPauseMonitor:109 - JvmPauseMonitor-192.168.42.91-40010: Stopped

jmap信息

Jun 09 '22 13:06 BanDuWuZi

开始执行remove peer后的全部日志

2022-06-09 21:19:04,990 [pool-1-IoTDB-InternalServiceRPC-Client-5] INFO o.a.i.d.s.t.i.InternalServiceImpl:484 - succeed to add new peer TEndPoint(ip:192.168.42.128, port:40010) for the region: SchemaRegion[0] 2022-06-09 21:19:04,991 [pool-1-IoTDB-InternalServiceRPC-Client-5] INFO o.a.i.d.s.t.i.InternalServiceImpl:486 - start to remove old peer TEndPoint(ip:192.168.42.91, port:40010) for the region: SchemaRegion[0] 2022-06-09 21:19:04,996 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.91-40010@group-000200000000: set configuration 15: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,001 [grpc-default-executor-0] INFO o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:140 - 192.168.42.91-40010: Completed APPEND_ENTRIES, lastRequest: 192.168.42.74-40010->192.168.42.91-40010#18-t2,previous=(t:2, i:14),leaderCommit=14,initializing? true,entries: size=1, first=(t:2, i:15), CONFIGURATIONENTRY 2022-06-09 21:19:13,249 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,461 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,893 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,104 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,426 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,637 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,182 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,393 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,936 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,258 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,685 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,896 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,106 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,428 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,638 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,848 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,167 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,377 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,237 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,556 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,766 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,087 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,296 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,614 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,823 [192.168.42.91-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.91-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.91-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,892 [192.168.42.91-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.FollowerState:143 - 192.168.42.91-40010@group-000200000000-FollowerState: change to CANDIDATE, lastRpcElapsedTime:8879288172ns, electionTimeout:5514ms 2022-06-09 21:19:20,892 [192.168.42.91-40010@group-000200000000-FollowerState] INFO o.a.r.s.impl.RoleInfo:110 - 192.168.42.91-40010: shutdown 192.168.42.91-40010@group-000200000000-FollowerState 2022-06-09 21:19:20,892 [192.168.42.91-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.RaftServerImpl:299 - 192.168.42.91-40010@group-000200000000: changes role from FOLLOWER to CANDIDATE at term 2 for changeToCandidate 2022-06-09 21:19:20,893 [192.168.42.91-40010@group-000200000000-FollowerState] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.leaderelection.pre-vote = true (default) 2022-06-09 21:19:20,893 [192.168.42.91-40010@group-000200000000-FollowerState] INFO o.a.r.s.impl.RoleInfo:139 - 192.168.42.91-40010: start 192.168.42.91-40010@group-000200000000-LeaderElection15 2022-06-09 21:19:20,893 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.impl.ServerState:287 - 192.168.42.91-40010@group-000200000000: change Leader from 192.168.42.74-40010 to null at term 2 for PRE_VOTE 2022-06-09 21:19:20,893 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.i.LeaderElection:310 - 192.168.42.91-40010@group-000200000000-LeaderElection15 PRE_VOTE round 0: submit vote requests at term 2 for 15: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,893 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.i.LeaderElection:312 - 192.168.42.91-40010@group-000200000000-LeaderElection15 PRE_VOTE round 0: result NOT_IN_CONF (term=2) 2022-06-09 21:19:20,894 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.i.RaftServerProxy:398 - 192.168.42.91-40010: close 2022-06-09 21:19:20,896 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.i.RaftServerImpl:434 - 192.168.42.91-40010@group-000200000000: shutdown 2022-06-09 21:19:20,897 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.util.JmxRegister:73 - Successfully un-registered JMX Bean with object name Ratis:service=RaftServer,group=group-000200000000,id=192.168.42.91-40010 2022-06-09 21:19:20,897 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.impl.RoleInfo:130 - 192.168.42.91-40010: shutdown 192.168.42.91-40010@group-000200000000-LeaderElection15 2022-06-09 21:19:20,897 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.i.StateMachineUpdater:153 - 192.168.42.91-40010@group-000200000000-StateMachineUpdater: set stopIndex = 14 2022-06-09 21:19:20,901 [192.168.42.91-40010@group-000200000000-StateMachineUpdater] INFO o.a.r.s.i.StateMachineUpdater:287 - 192.168.42.91-40010@group-000200000000-StateMachineUpdater: Took a snapshot at index 14 2022-06-09 21:19:20,901 [192.168.42.91-40010@group-000200000000-StateMachineUpdater] INFO o.a.r.s.i.StateMachineUpdater:92 - 192.168.42.91-40010@group-000200000000-StateMachineUpdater: snapshotIndex: updateIncreasingly -1 -> 14 2022-06-09 21:19:20,901 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.impl.ServerState:429 - 192.168.42.91-40010@group-000200000000: closes. applyIndex: 14 2022-06-09 21:19:20,902 [192.168.42.91-40010@group-000200000000-SegmentedRaftLogWorker] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:336 - 192.168.42.91-40010@group-000200000000-SegmentedRaftLogWorker was interrupted, exiting. There are 0 tasks remaining in the queue. 2022-06-09 21:19:20,903 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:246 - 192.168.42.91-40010@group-000200000000-SegmentedRaftLogWorker close() 2022-06-09 21:19:20,904 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.g.s.GrpcService:269 - 192.168.42.91-40010: shutdown server with port 40010 now 2022-06-09 21:19:20,913 [192.168.42.91-40010@group-000200000000-LeaderElection15] INFO o.a.r.g.s.GrpcService:278 - 192.168.42.91-40010: shutdown server with port 40010 successfully 2022-06-09 21:19:20,913 [org.apache.ratis.util.JvmPauseMonitor$$Lambda$142/307605969@464649c] INFO o.a.r.u.JvmPauseMonitor:109 - JvmPauseMonitor-192.168.42.91-40010: Stopped

Jun 09 '22 13:06 BanDuWuZi

上面91节点日志起止时间：2022-06-09 21:19:04,990 -- 2022-06-09 21:19:20,913 关键字：start to remove old peer TEndPoint(ip:192.168.42.91, port:40010) for the region: SchemaRegion[0] group-000200000000

对应时间段的74节点日志如下： 2022-06-09 21:18:52,041 [192.168.42.74-40010@group-000100000002-FollowerState] INFO o.a.r.s.i.FollowerState:143 - 192.168.42.74-40010@group-000100000002-FollowerState: change to CANDIDATE, lastRpcElapsedTime:4383348938ns, electionTimeout:4383ms 2022-06-09 21:18:55,464 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.impl.ServerState:287 - 192.168.42.74-40010@group-000100000002: change Leader from null to 192.168.42.128-40010 at term 2 for appendEntries, leader elected after 7809ms 2022-06-09 21:19:00,622 [grpc-default-executor-2] INFO o.a.r.s.i.RaftServerImpl:1152 - 192.168.42.74-40010@group-000200000000: receive requestVote(PRE_VOTE, 192.168.42.128-40010, group-000200000000, 0, (t:0, i:0)) 2022-06-09 21:18:52,041 [192.168.42.74-40010@group-000100000002-FollowerState] INFO o.a.r.s.i.FollowerState:143 - 192.168.42.74-40010@group-000100000002-FollowerState: change to CANDIDATE, lastRpcElapsedTime:4383348938ns, electionTimeout:4383ms 2022-06-09 21:18:55,464 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.impl.ServerState:287 - 192.168.42.74-40010@group-000100000002: change Leader from null to 192.168.42.128-40010 at term 2 for appendEntries, leader elected after 7809ms 2022-06-09 21:19:00,318 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:00,536 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:00,622 [grpc-default-executor-2] INFO o.a.r.s.i.RaftServerImpl:1152 - 192.168.42.74-40010@group-000200000000: receive requestVote(PRE_VOTE, 192.168.42.128-40010, group-000200000000, 0, (t:0, i:0)) 2022-06-09 21:19:00,622 [grpc-default-executor-2] INFO o.a.r.s.impl.VoteContext:48 - 192.168.42.74-40010@group-000200000000-FOLLOWER: reject PRE_VOTE from 192.168.42.128-40010: 192.168.42.128-40010 is not in current conf [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:00,623 [grpc-default-executor-2] INFO o.a.r.s.i.RaftServerImpl:1184 - 192.168.42.74-40010@group-000200000000 replies to PRE_VOTE vote request: 192.168.42.128-40010<-192.168.42.74-40010#0:FAIL-t1. Peer's state: 192.168.42.74-40010@group-000200000000:t1, leader=192.168.42.91-40010, voted=192.168.42.91-40010, raftlog=192.168.42.74-40010@group-000200000000-SegmentedRaftLog:OPENED:c7, conf=7: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:00,748 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:00,962 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:01,173 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:01,389 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:01,546 [grpc-default-executor-2] INFO o.a.r.s.i.RaftServerImpl:1152 - 192.168.42.74-40010@group-000200000000: receive requestVote(PRE_VOTE, 192.168.42.91-40010, group-000200000000, 1, (t:1, i:8)) 2022-06-09 21:19:01,546 [grpc-default-executor-2] INFO o.a.r.s.impl.VoteContext:48 - 192.168.42.74-40010@group-000200000000-FOLLOWER: reject PRE_VOTE from 192.168.42.91-40010: our priority 1 > candidate's priority 0 2022-06-09 21:19:01,546 [grpc-default-executor-2] INFO o.a.r.s.i.RaftServerImpl:1184 - 192.168.42.74-40010@group-000200000000 replies to PRE_VOTE vote request: 192.168.42.91-40010<-192.168.42.74-40010#0:FAIL-t1. Peer's state: 192.168.42.74-40010@group-000200000000:t1, leader=192.168.42.91-40010, voted=192.168.42.91-40010, raftlog=192.168.42.74-40010@group-000200000000-SegmentedRaftLog:OPENED:c7, conf=7: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:01,621 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:01,860 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:02,083 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:02,312 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:02,571 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:02,783 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:02,998 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:03,209 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:03,420 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:03,634 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:03,844 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,054 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,265 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,297 [grpc-default-executor-3] INFO o.a.r.s.i.RaftServerImpl:1152 - 192.168.42.74-40010@group-000200000000: receive requestVote(PRE_VOTE, 192.168.42.91-40010, group-000200000000, 1, (t:1, i:8)) 2022-06-09 21:19:04,297 [grpc-default-executor-3] INFO o.a.r.s.impl.VoteContext:48 - 192.168.42.74-40010@group-000200000000-FOLLOWER: reject PRE_VOTE from 192.168.42.91-40010: our priority 1 > candidate's priority 0 2022-06-09 21:19:04,297 [grpc-default-executor-3] INFO o.a.r.s.i.RaftServerImpl:1184 - 192.168.42.74-40010@group-000200000000 replies to PRE_VOTE vote request: 192.168.42.91-40010<-192.168.42.74-40010#0:FAIL-t1. Peer's state: 192.168.42.74-40010@group-000200000000:t1, leader=192.168.42.91-40010, voted=192.168.42.91-40010, raftlog=192.168.42.74-40010@group-000200000000-SegmentedRaftLog:OPENED:c7, conf=7: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:04,474 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,686 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,851 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.FollowerState:143 - 192.168.42.74-40010@group-000200000000-FollowerState: change to CANDIDATE, lastRpcElapsedTime:9190828891ns, electionTimeout:4888ms 2022-06-09 21:19:04,852 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.impl.RoleInfo:110 - 192.168.42.74-40010: shutdown 192.168.42.74-40010@group-000200000000-FollowerState 2022-06-09 21:19:04,852 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.RaftServerImpl:299 - 192.168.42.74-40010@group-000200000000: changes role from FOLLOWER to CANDIDATE at term 1 for changeToCandidate 2022-06-09 21:19:04,852 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.leaderelection.pre-vote = true (default) 2022-06-09 21:19:04,852 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.impl.RoleInfo:139 - 192.168.42.74-40010: start 192.168.42.74-40010@group-000200000000-LeaderElection10 2022-06-09 21:19:04,853 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.impl.ServerState:287 - 192.168.42.74-40010@group-000200000000: change Leader from 192.168.42.91-40010 to null at term 1 for PRE_VOTE 2022-06-09 21:19:04,853 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:310 - 192.168.42.74-40010@group-000200000000-LeaderElection10 PRE_VOTE round 0: submit vote requests at term 1 for 7: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:04,856 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:90 - 192.168.42.74-40010@group-000200000000-LeaderElection10: PRE_VOTE PASSED received 1 response(s) and 0 exception(s): 2022-06-09 21:19:04,856 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:94 - Response 0: 192.168.42.74-40010<-192.168.42.91-40010#0:OK-t1 2022-06-09 21:19:04,856 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:312 - 192.168.42.74-40010@group-000200000000-LeaderElection10 PRE_VOTE round 0: result PASSED 2022-06-09 21:19:04,866 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:310 - 192.168.42.74-40010@group-000200000000-LeaderElection10 ELECTION round 0: submit vote requests at term 2 for 7: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:04,871 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:90 - 192.168.42.74-40010@group-000200000000-LeaderElection10: ELECTION PASSED received 1 response(s) and 0 exception(s): 2022-06-09 21:19:04,872 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:94 - Response 0: 192.168.42.74-40010<-192.168.42.91-40010#0:OK-t2 2022-06-09 21:19:04,872 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.LeaderElection:312 - 192.168.42.74-40010@group-000200000000-LeaderElection10 ELECTION round 0: result PASSED 2022-06-09 21:19:04,872 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.impl.RoleInfo:130 - 192.168.42.74-40010: shutdown 192.168.42.74-40010@group-000200000000-LeaderElection10 2022-06-09 21:19:04,872 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.i.RaftServerImpl:299 - 192.168.42.74-40010@group-000200000000: changes role from CANDIDATE to LEADER at term 2 for changeToLeader 2022-06-09 21:19:04,872 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.impl.ServerState:287 - 192.168.42.74-40010@group-000200000000: change Leader from null to 192.168.42.74-40010 at term 2 for becomeLeader, leader elected after 19ms 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.staging.catchup.gap = 1000 (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.write.element-limit = 4096 (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.write.byte-limit = 64MB (=67108864) (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.watch.timeout = 10s (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.watch.timeout.denomination = 1s (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.watch.element-limit = 65536 (default) 2022-06-09 21:19:04,873 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.write.element-limit = 4096 (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.write.follower.gap.ratio.max = -1.0 (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.buffer.byte-limit = 4MB (=4194304) (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.buffer.element-limit = 0 (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.grpc.server.leader.outstanding.appends.max = 128 (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.rpc.request.timeout = 3000ms (default) 2022-06-09 21:19:04,874 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.install.snapshot.enabled = true (default) 2022-06-09 21:19:04,875 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.impl.RoleInfo:139 - 192.168.42.74-40010: start 192.168.42.74-40010@group-000200000000-LeaderStateImpl 2022-06-09 21:19:04,875 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:430 - 192.168.42.74-40010@group-000200000000-SegmentedRaftLogWorker: Rolling segment log-0_8 to index:8 2022-06-09 21:19:04,875 [192.168.42.74-40010@group-000200000000-LeaderElection10] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.74-40010@group-000200000000: set configuration 9: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:04,876 [192.168.42.74-40010@group-000200000000-SegmentedRaftLogWorker] INFO o.a.r.s.r.s.SegmentedRaftLogWorker$FinalizeLogSegment:586 - 192.168.42.74-40010@group-000200000000-SegmentedRaftLogWorker: Rolled log segment from /home/qsw/my_iotdb_cluster/datanode/sbin/../data/consensus/47474747-4747-4747-4747-000200000000/current/log_inprogress_0 to /home/qsw/my_iotdb_cluster/datanode/sbin/../data/consensus/47474747-4747-4747-4747-000200000000/current/log_0-8 2022-06-09 21:19:04,888 [192.168.42.74-40010@group-000200000000-SegmentedRaftLogWorker] INFO o.a.r.s.r.s.SegmentedRaftLogWorker$StartLogSegment:629 - 192.168.42.74-40010@group-000200000000-SegmentedRaftLogWorker: created new log segment /home/qsw/my_iotdb_cluster/datanode/sbin/../data/consensus/47474747-4747-4747-4747-000200000000/current/log_inprogress_9 2022-06-09 21:19:04,898 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,898 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.LeaderStateImpl:368 - 192.168.42.74-40010@group-000200000000-LeaderStateImpl: startSetConfiguration SetConfigurationRequest:client-680C5708027F->192.168.42.74-40010@group-000200000000, cid=41, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,898 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default) 2022-06-09 21:19:04,898 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.buffer.byte-limit = 4MB (=4194304) (default) 2022-06-09 21:19:04,899 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.buffer.element-limit = 0 (default) 2022-06-09 21:19:04,899 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.grpc.server.leader.outstanding.appends.max = 128 (default) 2022-06-09 21:19:04,899 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.rpc.request.timeout = 3000ms (default) 2022-06-09 21:19:04,899 [192.168.42.74-40010-server-thread1] INFO o.a.ratis.conf.ConfUtils:46 - raft.server.log.appender.install.snapshot.enabled = true (default) 2022-06-09 21:19:04,899 [192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender-LogAppenderDaemon] INFO o.a.r.s.i.FollowerInfoImpl:118 - Follower 192.168.42.74-40010@group-000200000000->192.168.42.128-40010 acknowledged installing snapshot 2022-06-09 21:19:04,982 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.74-40010@group-000200000000: set configuration 11: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,986 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.74-40010@group-000200000000: set configuration 13: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=null 2022-06-09 21:19:04,995 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,995 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.LeaderStateImpl:368 - 192.168.42.74-40010@group-000200000000-LeaderStateImpl: startSetConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:04,995 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.impl.ServerState:393 - 192.168.42.74-40010@group-000200000000: set configuration 15: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:07,996 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: appendEntries Timeout, request=AppendEntriesRequest:cid=18,entriesCount=1,lastEntry=(t:2, i:15) 2022-06-09 21:19:08,992 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=117,entriesCount=0,lastEntry=null 2022-06-09 21:19:09,493 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=167,entriesCount=0,lastEntry=null 2022-06-09 21:19:09,994 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=217,entriesCount=0,lastEntry=null 2022-06-09 21:19:10,496 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=267,entriesCount=0,lastEntry=null 2022-06-09 21:19:10,997 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=317,entriesCount=0,lastEntry=null 2022-06-09 21:19:11,497 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=366,entriesCount=0,lastEntry=null 2022-06-09 21:19:11,998 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=415,entriesCount=0,lastEntry=null 2022-06-09 21:19:12,499 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=465,entriesCount=0,lastEntry=null 2022-06-09 21:19:12,998 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] WARN o.a.r.s.i.LeaderStateImpl:1018 - 192.168.42.74-40010@group-000200000000-LeaderStateImpl: Lost leadership on term: 2. Election timeout: 8000ms. In charge for: 8125ms. Conf: 15: [192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0], old=[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91-40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:12,999 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] WARN o.a.r.s.i.LeaderStateImpl:1022 - Follower 192.168.42.74-40010@group-000200000000->192.168.42.91-40010(c14,m15,n16, attendVote=true, lastRpcSendTime=986, lastRpcResponseTime=985) 2022-06-09 21:19:12,999 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] WARN o.a.r.s.i.LeaderStateImpl:1022 - Follower 192.168.42.74-40010@group-000200000000->192.168.42.128-40010(c13,m14,n16, attendVote=true, lastRpcSendTime=495, lastRpcResponseTime=8007) 2022-06-09 21:19:12,999 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.i.RaftServerImpl:299 - 192.168.42.74-40010@group-000200000000: changes role from LEADER to FOLLOWER at term 2 for StepDownReason:LOST_MAJORITY_HEARTBEATS 2022-06-09 21:19:12,999 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.impl.RoleInfo:93 - 192.168.42.74-40010: shutdown 192.168.42.74-40010@group-000200000000-LeaderStateImpl 2022-06-09 21:19:12,999 [java.util.concurrent.ThreadPoolExecutor$Worker@520ba620[State = -1, empty queue]] WARN o.a.r.g.s.GrpcLogAppender:239 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: HEARTBEAT appendEntries Timeout, request=AppendEntriesRequest:cid=514,entriesCount=0,lastEntry=null 2022-06-09 21:19:13,000 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.i.PendingRequests:282 - 192.168.42.74-40010@group-000200000000-PendingRequests: sendNotLeaderResponses 2022-06-09 21:19:13,000 [192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender-LogAppenderDaemon] WARN o.a.r.g.s.GrpcLogAppender:171 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-GrpcLogAppender: Wait interrupted by java.lang.InterruptedException 2022-06-09 21:19:13,000 [192.168.42.74-40010@group-000200000000->192.168.42.91-40010-GrpcLogAppender-LogAppenderDaemon] WARN o.a.r.g.s.GrpcLogAppender:171 - 192.168.42.74-40010@group-000200000000->192.168.42.91-40010-GrpcLogAppender: Wait interrupted by java.lang.InterruptedException 2022-06-09 21:19:13,001 [192.168.42.74-40010@group-000200000000-LeaderStateImpl] INFO o.a.r.s.impl.RoleInfo:139 - 192.168.42.74-40010: start 192.168.42.74-40010@group-000200000000-FollowerState 2022-06-09 21:19:13,002 [grpc-default-executor-3] INFO o.a.r.g.s.GrpcLogAppender$AppendLogResponseHandler:339 - 192.168.42.74-40010@group-000200000000->192.168.42.91-40010-AppendLogResponseHandler: follower responses appendEntries COMPLETED 2022-06-09 21:19:13,002 [grpc-default-executor-3] INFO o.a.r.s.i.FollowerInfoImpl:48 - 192.168.42.74-40010@group-000200000000->192.168.42.91-40010: nextIndex: updateUnconditionally 16 -> 15 2022-06-09 21:19:13,003 [grpc-default-executor-2] INFO o.a.r.g.s.GrpcLogAppender$AppendLogResponseHandler:339 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010-AppendLogResponseHandler: follower responses appendEntries COMPLETED 2022-06-09 21:19:13,003 [grpc-default-executor-2] INFO o.a.r.s.i.FollowerInfoImpl:48 - 192.168.42.74-40010@group-000200000000->192.168.42.128-40010: nextIndex: updateUnconditionally 16 -> 15 2022-06-09 21:19:13,356 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,567 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,787 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:13,999 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,210 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,533 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,743 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:14,963 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,288 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,499 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:15,720 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,042 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,364 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,580 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:16,791 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,002 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,127 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.FollowerState:108 - 192.168.42.74-40010@group-000200000000-FollowerState: Skipping leader election since it stepped down recently (elapsed = 4125ms < waitTime = 10s) 2022-06-09 21:19:17,212 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,534 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,744 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:17,954 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,273 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,483 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,698 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:18,912 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,133 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,342 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,662 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:19,871 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,188 [192.168.42.74-40010@group-000200000000-FollowerState] INFO o.a.r.s.i.FollowerState:108 - 192.168.42.74-40010@group-000200000000-FollowerState: Skipping leader election since it stepped down recently (elapsed = 7186ms < waitTime = 10s) 2022-06-09 21:19:20,192 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,401 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,719 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:20,928 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:21,142 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:21,357 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:21,778 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:22,098 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:22,518 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:22,732 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:22,947 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] 2022-06-09 21:19:23,264 [192.168.42.74-40010-server-thread1] INFO o.a.r.s.i.RaftServerImpl:1080 - 192.168.42.74-40010@group-000200000000: receive setConfiguration SetConfigurationRequest:client-2E8311C00B6F->192.168.42.74-40010@group-000200000000, cid=42, seq=0, RW, null, peers:[192.168.42.74-40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.128-40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0]

Jun 10 '22 02:06 BanDuWuZi

最新全日志：日志见：IOTDB-3452

Jun 10 '22 07:06 BanDuWuZi

6/10下午回合社区最新代码后，测试

Jun 11 '22 01:06 BanDuWuZi

在128上添加共识组成功后 2022-06-11 16:09:48,127 [pool-1-IoTDB-InternalServiceRPC-Client-6] DEBUG o.a.i.d.s.t.i.InternalServiceImpl:637 - succeed to add peers [Peer{groupId=DataRegion[5], endpoint=TEndPoint(ip:192.168.42.91, port:40010)}, Peer{groupId=DataRegion[5], endpoint=TEndPoint(ip:192.168.42.74, port:40010)}, Peer{groupId=DataRegion[5], endpoint=TEndPoint(ip:192.168.42.128, port:40010)}] to region DataRegion[5] consensus group
在91执行上给128上addPeer时报错。 2022-06-11 16:10:47,970 [pool-1-IoTDB-InternalServiceRPC-Client-8] ERROR o.a.i.d.s.t.i.InternalServiceImpl:582 - add peer Peer{groupId=DataRegion[5], endpoint=TEndPoint(ip:192.168.42.128, port:40010)} for region DataRegion[5] error. org.apache.iotdb.consensus.exception.RatisRequestFailedException: Ratis request failed at org.apache.iotdb.consensus.ratis.RatisConsensus.sendReconfiguration(RatisConsensus.java:605) at org.apache.iotdb.consensus.ratis.RatisConsensus.addPeer(RatisConsensus.java:347) at org.apache.iotdb.db.service.thrift.impl.InternalServiceImpl.addPeer(InternalServiceImpl.java:573) at org.apache.iotdb.db.service.thrift.impl.InternalServiceImpl.migrateRegion(InternalServiceImpl.java:504) at org.apache.iotdb.mpp.rpc.thrift.InternalService$Processor$migrateRegion.getResult(InternalService.java:1805) at org.apache.iotdb.mpp.rpc.thrift.InternalService$Processor$migrateRegion.getResult(InternalService.java:1785) at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:38) at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:38) at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:248) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750) Caused by: org.apache.ratis.protocol.exceptions.RaftRetryFailureException: Failed SetConfigurationRequest:client-6B9164F25C4A->192.168.42.74_40010@group-000100000005, cid=9, seq=0, RW, null, peers:[192.168.42.74_40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91_40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128_40010|rpc:192.168.42.128:40010|priority:0] for 10 attempts with org.apache.iotdb.consensus.ratis.RatisClient$RatisRetryPolicy@7a936823 at org.apache.ratis.client.impl.RaftClientImpl.noMoreRetries(RaftClientImpl.java:295) at org.apache.ratis.client.impl.BlockingImpl.sendRequestWithRetry(BlockingImpl.java:117) at org.apache.ratis.client.impl.AdminImpl.setConfiguration(AdminImpl.java:47) at org.apache.ratis.client.api.AdminApi.setConfiguration(AdminApi.java:36) at org.apache.iotdb.consensus.ratis.RatisConsensus.sendReconfiguration(RatisConsensus.java:600) ... 11 common frames omitted Caused by: org.apache.ratis.protocol.exceptions.ReconfigurationTimeoutException: 192.168.42.74_40010@group-000100000005-ConfigurationStagingState: Fail to set configuration [192.168.42.74_40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91_40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128_40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] due to NOPROGRESS at org.apache.ratis.server.impl.LeaderStateImpl$ConfigurationStagingState.fail(LeaderStateImpl.java:1090) at org.apache.ratis.server.impl.LeaderStateImpl.checkStaging(LeaderStateImpl.java:704) at org.apache.ratis.server.impl.LeaderStateImpl.access$500(LeaderStateImpl.java:95) at org.apache.ratis.server.impl.LeaderStateImpl$EventProcessor.run(LeaderStateImpl.java:636) 2022-06-11 16:10:48,862 [192.168.42.91_40010@group-000100000002-FollowerState] INFO o.a.r.s.i.FollowerState:143 - 192.168.42.91_40010@group-000100000002-FollowerState: change to CANDIDATE, lastRpcElapsedTime:2452413198ns, electionTimeout:2452ms
74的同时段日志 2022-06-11 16:10:47,885 [ForkJoinPool.commonPool-worker-9] DEBUG o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:102 - 192.168.42.74_50010: reply 192.168.42.91_50010<-192.168.42.74_50010#320:OK-t1,SUCCESS,nextIndex=5,followerCommit=4 2022-06-11 16:10:47,885 [grpc-default-worker-ELG-3-3] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0xec460214, L:/192.168.42.74:50010 - R:/192.168.42.91:60374] OUTBOUND DATA: streamId=7 padding=0 endStream=false length=93 bytes=00000000580a430a133139322e3136382e34322e39315f353030313012133139322e3136382e34322e37345f35303031301a120a104747474747474747474700... 2022-06-11 16:10:47,890 [192.168.42.74_40010@group-000100000007->192.168.42.91_40010-GrpcLogAppender-LogAppenderDaemon] DEBUG o.a.r.u.TimeoutScheduler:154 - schedule a task: timeout 3000ms, sid 273 2022-06-11 16:10:47,890 [grpc-default-worker-ELG-3-13] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x7bd571c3, L:/192.168.42.74:35416 - R:192.168.42.91/192.168.42.91:40010] OUTBOUND DATA: streamId=7 padding=0 endStream=false length=174 bytes=00000000a90a430a133139322e3136382e34322e37345f343030313012133139322e3136382e34322e39315f34303031301a120a104747474747474747474700... 2022-06-11 16:10:47,891 [grpc-default-worker-ELG-3-13] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x7bd571c3, L:/192.168.42.74:35416 - R:192.168.42.91/192.168.42.91:40010] INBOUND DATA: streamId=7 padding=0 endStream=false length=91 bytes=00000000560a430a133139322e3136382e34322e37345f343030313012133139322e3136382e34322e39315f34303031301a120a104747474747474747474700... 2022-06-11 16:10:47,892 [grpc-default-executor-0] DEBUG o.a.r.g.s.GrpcLogAppender$AppendLogResponseHandler:277 - 192.168.42.74_40010@group-000100000007->192.168.42.91_40010-AppendLogResponseHandler: received a reply 192.168.42.74_40010<-192.168.42.91_40010#213:OK-t1,SUCCESS,nextIndex=1,followerCommit=0, request=AppendEntriesRequest:cid=213,entriesCount=0,lastEntry=null 2022-06-11 16:10:47,892 [grpc-default-executor-0] DEBUG o.a.r.s.i.FollowerInfoImpl:49 - 192.168.42.74_40010@group-000100000007->192.168.42.91_40010: commitIndex: updateToMax old=0, new=0, updated? false 2022-06-11 16:10:47,892 [grpc-default-executor-0] DEBUG o.a.r.s.i.FollowerInfoImpl:49 - 192.168.42.74_40010@group-000100000007->192.168.42.91_40010: matchIndex: updateToMax old=0, new=-1, updated? false 2022-06-11 16:10:47,960 [192.168.42.74_40010@group-000100000005-LeaderStateImpl] DEBUG o.a.r.s.i.LeaderStateImpl:662 - 192.168.42.74_40010@group-000100000005-LeaderStateImpl detects a follower 192.168.42.74_40010@group-000100000005->192.168.42.128_40010(c-1,m0,n11, attendVote=false, lastRpcSendTime=241, lastRpcResponseTime=12253) timeout (153.500s) for bootstrapping 2022-06-11 16:10:47,961 [192.168.42.74_40010@group-000100000005-LeaderStateImpl] DEBUG o.a.r.s.i.LeaderStateImpl$ConfigurationStagingState:1085 - 192.168.42.74_40010@group-000100000005-ConfigurationStagingState: Fail to set configuration [192.168.42.74_40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91_40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128_40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] due to NOPROGRESS 2022-06-11 16:10:47,961 [192.168.42.74_40010@group-000100000005-LeaderStateImpl] DEBUG o.a.r.m.RatisMetrics:46 - Unregistering Metrics Registry : ratis_grpc.log_appender.192.168.42.74_40010@group-000100000005 2022-06-11 16:10:47,961 [192.168.42.74_40010@group-000100000005-LeaderStateImpl] DEBUG o.a.r.u.LifeCycle$State:116 - 192.168.42.74_40010@group-000100000005->192.168.42.128_40010-GrpcLogAppender-LogAppenderDaemon: RUNNING -> CLOSING 2022-06-11 16:10:47,961 [192.168.42.74_40010@group-000100000005->192.168.42.128_40010-GrpcLogAppender-LogAppenderDaemon] DEBUG o.a.r.u.LifeCycle$State:116 - 192.168.42.74_40010@group-000100000005->192.168.42.128_40010-GrpcLogAppender-LogAppenderDaemon: CLOSING -> CLOSED 2022-06-11 16:10:47,963 [grpc-default-worker-ELG-3-10] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0xd8cf66ae, L:/192.168.42.74:40010 - R:/192.168.42.91:39066] OUTBOUND HEADERS: streamId=3 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, exception-type: org.apache.ratis.protocol.exceptions.ReconfigurationTimeoutException, exception-object-bin: rO0ABXNyAERvcmcuYXBhY2hlLnJhdGlzLnByb3RvY29sLmV4Y2VwdGlvbnMuUmVjb25maWd1cmF0aW9uVGltZW91dEV4Y2VwdGlvbmw90jhgLZ4SAgAAeHIAMm9yZy5hcGFjaGUucmF0aXMucHJvdG9jb2wuZXhjZXB0aW9ucy5SYWZ0RXhjZXB0aW9uAAAAAAAAAAECAAB4cgATamF2YS5pby5JT0V4Y2VwdGlvbmyAc2RlJfCrAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q/R8+GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4ACXQBaTE5Mi4xNjguNDIuNzRfNDAwMTBAZ3JvdXAtMDAwMTAwMDAwMDA1LUNvbmZpZ3VyYXRpb25TdGFnaW5nU3RhdGU6IEZhaWwgdG8gc2V0IGNvbmZpZ3VyYXRpb24gWzE5Mi4xNjguNDIuNzRfNDAwMTB8cnBjOjE5Mi4xNjguNDIuNzQ6NDAwMTB8YWRtaW46fGNsaWVudDp8ZGF0YVN0cmVhbTp8cHJpb3JpdHk6MSwgMTkyLjE2OC40Mi45MV80MDAxMHxycGM6MTkyLjE2OC40Mi45MTo0MDAxMHxhZG1pbjp8Y2xpZW50OnxkYXRhU3RyZWFtOnxwcmlvcml0eTowLCAxOTIuMTY4LjQyLjEyOF80MDAxMHxycGM6MTkyLjE2OC40Mi4xMjg6NDAwMTB8YWRtaW46fGNsaWVudDp8ZGF0YVN0cmVhbTp8cHJpb3JpdHk6MF0gZHVlIHRvIE5PUFJPR1JFU1N1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAARzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABkwACGZpbGVOYW1lcQB+AAZMAAptZXRob2ROYW1lcQB+AAZ4cAAABEJ0AEZvcmcuYXBhY2hlLnJhdGlzLnNlcnZlci5pbXBsLkxlYWRlclN0YXRlSW1wbCRDb25maWd1cmF0aW9uU3RhZ2luZ1N0YXRldAAUTGVhZGVyU3RhdGVJbXBsLmphdmF0AARmYWlsc3EAfgANAAACwHQALG9yZy5hcGFjaGUucmF0aXMuc2VydmVyLmltcGwuTGVhZGVyU3RhdGVJbXBscQB+ABB0AAxjaGVja1N0YWdpbmdzcQB+AA0AAABfcQB+ABNxAH4AEHQACmFjY2VzcyQ1MDBzcQB+AA0AAAJ8dAA7b3JnLmFwYWNoZS5yYXRpcy5zZXJ2ZXIuaW1wbC5MZWFkZXJTdGF0ZUltcGwkRXZlbnRQcm9jZXNzb3JxAH4AEHQAA3J1bnNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAIeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB+AB94, grpc-status: 13, grpc-message: 192.168.42.74_40010@group-000100000005-ConfigurationStagingState: Fail to set configuration [192.168.42.74_40010|rpc:192.168.42.74:40010|admin:|client:|dataStream:|priority:1, 192.168.42.91_40010|rpc:192.168.42.91:40010|admin:|client:|dataStream:|priority:0, 192.168.42.128_40010|rpc:192.168.42.128:40010|admin:|client:|dataStream:|priority:0] due to NOPROGRESS] padding=0 endStream=true 2022-06-11 16:10:47,968 [grpc-default-worker-ELG-3-10] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0xd8cf66ae, L:/192.168.42.74:40010 - R:/192.168.42.91:39066] INBOUND GO_AWAY: lastStreamId=0 errorCode=0 length=0 bytes= 2022-06-11 16:10:48,196 [java.util.concurrent.ThreadPoolExecutor$Worker@7068f2e5[State = -1, empty queue]] DEBUG o.a.r.u.TimeoutScheduler:139 - run a task: sid 262 2022-06-11 16:10:48,207 [192.168.42.74_40010@group-000100000005->192.168.42.91_40010-GrpcLogAppender-LogAppenderDaemon] DEBUG o.a.r.u.TimeoutScheduler:154 - schedule a task: timeout 3000ms, sid 274 2022-06-11 16:10:48,207 [grpc-default-worker-ELG-3-13] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x7bd571c3, L:/192.168.42.74:35416 - R:192.168.42.91/192.168.42.91:40010] OUTBOUND DATA: streamId=13 padding=0 endStream=false length=184 bytes=00000000b30a430a133139322e3136382e34322e37345f343030313012133139322e3136382e34322e39315f34303031301a120a104747474747474747474700... 2022-06-11 16:10:48,209 [grpc-default-worker-ELG-3-13] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x7bd571c3, L:/192.168.42.74:35416 - R:192.168.42.91/192.168.42.91:40010] INBOUND DATA: streamId=13 padding=0 endStream=false length=93 bytes=00000000580a430a133139322e3136382e34322e37345f343030313012133139322e3136382e34322e39315f34303031301a120a104747474747474747474700... 2022-06-11 16:10:48,210 [grpc-default-executor-0] DEBUG o.a.r.g.s.GrpcLogAppender$AppendLogResponseHandler:277 - 192.168.42.74_40010@group-000100000005->192.168.42.91_40010-AppendLogResponseHandler: received a reply 192.168.42.74_40010<-192.168.42.91_40010#157:OK-t2,SUCCESS,nextIndex=11,followerCommit=10, request=AppendEntriesRequest:cid=157,entriesCount=0,lastEntry=null

Jun 11 '22 08:06 BanDuWuZi

2022-06-16 20:36:20,535 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:246 - 192.168.42.74_40010@group-000100000006-SegmentedRaftLogWorker close() 2022-06-16 20:36:20,537 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.s.i.RaftServerImpl:434 - 192.168.42.74_40010@group-000100000007: shutdown 2022-06-16 20:36:20,537 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.util.JmxRegister:73 - Successfully un-registered JMX Bean with object name Ratis:service=RaftServer,group=group-000100000007,id=192.168.42.74_40010 2022-06-16 20:36:20,537 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.s.impl.RoleInfo:110 - 192.168.42.74_40010: shutdown 192.168.42.74_40010@group-000100000007-FollowerState 2022-06-16 20:36:20,537 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.s.i.StateMachineUpdater:153 - 192.168.42.74_40010@group-000100000007-StateMachineUpdater: set stopIndex = 0 2022-06-16 20:36:20,538 [ForkJoinPool.commonPool-worker-2] INFO o.a.r.s.impl.ServerState:429 - 192.168.42.74_40010@group-000100000007: closes. applyIndex: 0 2022-06-16 20:36:20,538 [192.168.42.74_40010@group-000100000007-FollowerState] INFO o.a.r.s.i.FollowerState:152 - 192.168.42.74_40010@group-000100000007-FollowerState was interrupted 2022-06-16 20:36:20,539 [192.168.42.74_40010@group-000100000003-StateMachineUpdater] ERROR o.a.r.s.i.StateMachineUpdater:194 - 192.168.42.74_40010@group-000100000003-StateMachineUpdater caught a Throwable. java.lang.NullPointerException: null at org.apache.iotdb.db.consensus.statemachine.DataRegionStateMachine.takeSnapshot(DataRegionStateMachine.java:70) at org.apache.iotdb.consensus.ratis.ApplicationStateMachineProxy.takeSnapshot(ApplicationStateMachineProxy.java:163) at org.apache.ratis.server.impl.StateMachineUpdater.takeSnapshot(StateMachineUpdater.java:270) at org.apache.ratis.server.impl.StateMachineUpdater.checkAndTakeSnapshot(StateMachineUpdater.java:262) at org.apache.ratis.server.impl.StateMachineUpdater.run(StateMachineUpdater.java:183) at java.lang.Thread.run(Thread.java:750) 2022-06-16 20:36:20,538 [192.168.42.74_40010@group-000100000007-SegmentedRaftLogWorker] INFO o.a.r.s.r.s.SegmentedRaftLogWorker:336 - 192.168.42.74_40010@group-000100000007-SegmentedRaftLogWorker was interrupted, exiting. There are 0 tasks remaining in the queue. 2022-06-16 20:36:20,541 [192.168.42.74_40010@group-000100000003-StateMachineUpdater] ERROR o.a.r.s.i.StateMachineUpdater:194 - 192.168.42.74_40010@group-000100000003-StateMachineUpdater caught a Throwable. java.lang.NullPointerException: null at org.apache.iotdb.db.consensus.statemachine.DataRegionStateMachine.takeSnapshot(DataRegionStateMachine.java:70) at org.apache.iotdb.consensus.ratis.ApplicationStateMachineProxy.takeSnapshot(ApplicationStateMachineProxy.java:163) at org.apache.ratis.server.impl.StateMachineUpdater.takeSnapshot(StateMachineUpdater.java:270) at org.apache.ratis.server.impl.StateMachineUpdater.checkAndTakeSnapshot(StateMachineUpdater.java:262) at org.apache.ratis.server.impl.StateMachineUpdater.run(StateMachineUpdater.java:183) at java.lang.Thread.run(Thread.java:750) 2022-06-16 20:36:20,542 [192.168.42.74_40010@group-000100000003-StateMachineUpdater] ERROR o.a.r.s.i.StateMachineUpdater:194 - 192.168.42.74_40010@group-000100000003-StateMachineUpdater caught a Throwable.

Jun 16 '22 12:06 BanDuWuZi

1. ConfigNode 2022-06-22 16:19:45发起region迁移请求，2022-06-22 16:20:54收到迁移失败，原因是add peer 失败。

2022-06-22 16:19:45,001 [Exec-RemoveDataNode-Thread] DEBUG o.a.i.c.m.DataNodeRemoveManager:449 - send region TConsensusGroupId(type:DataRegion, id:11) migrate action to TDataNodeLocation(dataNodeId:2, externalEndPoint:TEndPoint(ip:192.168.42.196, port:6697), internalEndPoint:TEndPoint(ip:192.168.42.196, port:9009), dataBlockManagerEndPoint:TEndPoint(ip:192.168.42.196, port:8797), dataRegionConsensusEndPoint:TEndPoint(ip:192.168.42.196, port:40090), schemaRegionConsensusEndPoint:TEndPoint(ip:192.168.42.196, port:50090)), wait it finished

2022-06-22 16:20:54,065 [pool-2-IoTDB-ConfigNodeRPC-Client-16] DEBUG o.a.i.c.m.DataNodeRemoveManager:498 - accept region TConsensusGroupId(type:DataRegion, id:11) migrate result, result: TRegionMigrateResultReportReq(regionId:TConsensusGroupId(type:DataRegion, id:11), migrateResult:TSStatus(code:911, message:add peer: TEndPoint(ip:192.168.42.16, port:40090) for region: DataRegion[11] failed. exception: Ratis request failed), failedNodeAndReason:{TDataNodeLocation(dataNodeId:1, externalEndPoint:TEndPoint(ip:192.168.42.16, port:6697), internalEndPoint:TEndPoint(ip:192.168.42.16, port:9009), dataBlockManagerEndPoint:TEndPoint(ip:192.168.42.16, port:8797), dataRegionConsensusEndPoint:TEndPoint(ip:192.168.42.16, port:40090), schemaRegionConsensusEndPoint:TEndPoint(ip:192.168.42.16, port:50090))=AddPeerFailed})

要缩容的节点上，执行region 11 的 addPeer时的jstack如下，会执行setConfiguration方法 "pool-20-IoTDB-Region-Migrate-Pool-1" #163 prio=5 os_prio=0 tid=0x0000fffe2403f800 nid=0x59f9 waiting on condition [0x0000fffd6b9f6000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at java.lang.Thread.sleep(Thread.java:342) at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386) at org.apache.ratis.util.TimeDuration.sleep(TimeDuration.java:325) at org.apache.ratis.util.TimeDuration.sleep(TimeDuration.java:310) at org.apache.ratis.client.impl.BlockingImpl.sendRequestWithRetry(BlockingImpl.java:121) at org.apache.ratis.client.impl.AdminImpl.setConfiguration(AdminImpl.java:47) at org.apache.ratis.client.api.AdminApi.setConfiguration(AdminApi.java:36) at org.apache.iotdb.consensus.ratis.RatisConsensus.sendReconfiguration(RatisConsensus.java:621) at org.apache.iotdb.consensus.ratis.RatisConsensus.addPeer(RatisConsensus.java:348) at org.apache.iotdb.db.service.RegionMigrateService$RegionMigrateTask.addPeer(RegionMigrateService.java:259) at org.apache.iotdb.db.service.RegionMigrateService$RegionMigrateTask.run(RegionMigrateService.java:160) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750) 缩容节点16:20:54报错日志如下 2022-06-22 16:20:54,050 [grpc-default-worker-ELG-3-12] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x262750fe, L:/192.168.42.196:39172 - R:192.168.42.204/192.168.42.204:40090] INBOUND HEADERS: streamId=3 headers=GrpcHttp2ResponseHeaders[:status: 200, content-type: application/grpc, exception-type: org.apache.ratis.protocol.exceptions.ReconfigurationTimeoutException, exception-object-bin: rO0ABXNyAERvcmcuYXBhY2hlLnJhdGlzLnByb3RvY29sLmV4Y2VwdGlvbnMuUmVjb25maWd1cmF0aW9uVGltZW91dEV4Y2VwdGlvbmw90jhgLZ4SAgAAeHIAMm9yZy5hcGFjaGUucmF0aXMucHJvdG9jb2wuZXhjZXB0aW9ucy5SYWZ0RXhjZXB0aW9uAAAAAAAAAAECAAB4cgATamF2YS5pby5JT0V4Y2VwdGlvbmyAc2RlJfCrAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q/R8+GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4ACXQBbDE5Mi4xNjguNDIuMjA0XzQwMDkwQGdyb3VwLTAwMDEwMDAwMDAwQi1Db25maWd1cmF0aW9uU3RhZ2luZ1N0YXRlOiBGYWlsIHRvIHNldCBjb25maWd1cmF0aW9uIFsxOTIuMTY4LjQyLjE2XzQwMDkwfHJwYzoxOTIuMTY4LjQyLjE2OjQwMDkwfGFkbWluOnxjbGllbnQ6fGRhdGFTdHJlYW06fHByaW9yaXR5OjAsIDE5Mi4xNjguNDIuMTk2XzQwMDkwfHJwYzoxOTIuMTY4LjQyLjE5Njo0MDA5MHxhZG1pbjp8Y2xpZW50OnxkYXRhU3RyZWFtOnxwcmlvcml0eTowLCAxOTIuMTY4LjQyLjIwNF80MDA5MHxycGM6MTkyLjE2OC40Mi4yMDQ6NDAwOTB8YWRtaW46fGNsaWVudDp8ZGF0YVN0cmVhbTp8cHJpb3JpdHk6MV0gZHVlIHRvIE5PUFJPR1JFU1N1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAARzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABkwACGZpbGVOYW1lcQB+AAZMAAptZXRob2ROYW1lcQB+AAZ4cAAABEJ0AEZvcmcuYXBhY2hlLnJhdGlzLnNlcnZlci5pbXBsLkxlYWRlclN0YXRlSW1wbCRDb25maWd1cmF0aW9uU3RhZ2luZ1N0YXRldAAUTGVhZGVyU3RhdGVJbXBsLmphdmF0AARmYWlsc3EAfgANAAACwHQALG9yZy5hcGFjaGUucmF0aXMuc2VydmVyLmltcGwuTGVhZGVyU3RhdGVJbXBscQB+ABB0AAxjaGVja1N0YWdpbmdzcQB+AA0AAABfcQB+ABNxAH4AEHQACmFjY2VzcyQ1MDBzcQB+AA0AAAJ8dAA7b3JnLmFwYWNoZS5yYXRpcy5zZXJ2ZXIuaW1wbC5MZWFkZXJTdGF0ZUltcGwkRXZlbnRQcm9jZXNzb3JxAH4AEHQAA3J1bnNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAIeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB+AB94, grpc-status: 13, grpc-message: 192.168.42.204_40090@group-00010000000B-ConfigurationStagingState: Fail to set configuration [192.168.42.16_40090|rpc:192.168.42.16:40090|admin:|client:|dataStream:|priority:0, 192.168.42.196_40090|rpc:192.168.42.196:40090|admin:|client:|dataStream:|priority:0, 192.168.42.204_40090|rpc:192.168.42.204:40090|admin:|client:|dataStream:|priority:1] due to NOPROGRESS] padding=0 endStream=true 2022-06-22 16:20:54,054 [pool-20-IoTDB-Region-Migrate-Pool-1] DEBUG o.a.r.c.i.RaftClientImpl:355 - client-7BC1E2CE1983: suggested new leader: null. Failed SetConfigurationRequest:client-7BC1E2CE1983->192.168.42.204_40090@group-00010000000B, cid=19, seq=0, RW, null, peers:[192.168.42.16_40090|rpc:192.168.42.16:40090|priority:0, 192.168.42.196_40090|rpc:192.168.42.196:40090|admin:|client:|dataStream:|priority:0, 192.168.42.204_40090|rpc:192.168.42.204:40090|admin:|client:|dataStream:|priority:1] with {} org.apache.ratis.protocol.exceptions.ReconfigurationTimeoutException: 192.168.42.204_40090@group-00010000000B-ConfigurationStagingState: Fail to set configuration [192.168.42.16_40090|rpc:192.168.42.16:40090|admin:|client:|dataStream:|priority:0, 192.168.42.196_40090|rpc:192.168.42.196:40090|admin:|client:|dataStream:|priority:0, 192.168.42.204_40090|rpc:192.168.42.204:40090|admin:|client:|dataStream:|priority:1] due to NOPROGRESS at org.apache.ratis.server.impl.LeaderStateImpl$ConfigurationStagingState.fail(LeaderStateImpl.java:1090) at org.apache.ratis.server.impl.LeaderStateImpl.checkStaging(LeaderStateImpl.java:704) at org.apache.ratis.server.impl.LeaderStateImpl.access$500(LeaderStateImpl.java:95) at org.apache.ratis.server.impl.LeaderStateImpl$EventProcessor.run(LeaderStateImpl.java:636)
看204节点日志16:20:54 2022-06-22 16:20:54,044 [192.168.42.204_40090@group-00010000000B-LeaderStateImpl] DEBUG o.a.r.s.i.LeaderStateImpl$ConfigurationStagingState:1085 - 192.168.42.204_40090@group-00010000000B-ConfigurationStagingState: Fail to set configuration [192.168.42.16_40090|rpc:192.168.42.16:40090|admin:|client:|dataStream:|priority:0, 192.168.42.196_40090|rpc:192.168.42.196:40090|admin:|client:|dataStream:|priority:0, 192.168.42.204_40090|rpc:192.168.42.204:40090|admin:|client:|dataStream:|priority:1] due to NOPROGRESS 2022-06-22 16:20:54,044 [192.168.42.204_40090@group-00010000000B-LeaderStateImpl] DEBUG o.a.r.m.RatisMetrics:46 - Unregistering Metrics Registry : ratis_grpc.log_appender.192.168.42.204_40090@group-00010000000B 2022-06-22 16:20:54,044 [192.168.42.204_40090@group-00010000000B-LeaderStateImpl] DEBUG o.a.r.u.LifeCycle$State:116 - 192.168.42.204_40090@group-00010000000B->192.168.42.16_40090-GrpcLogAppender-LogAppenderDaemon: RUNNING -> CLOSING 2022-06-22 16:20:54,045 [192.168.42.204_40090@group-00010000000B->192.168.42.16_40090-GrpcLogAppender-LogAppenderDaemon] DEBUG o.a.r.u.LifeCycle$State:116 - 192.168.42.204_40090@group-00010000000B->192.168.42.16_40090-GrpcLogAppender-LogAppenderDaemon: CLOSING -> CLOSED 2022-06-22 16:20:54,047 [grpc-default-worker-ELG-3-13] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x38e2240f, L:/192.168.42.204:40090 - R:/192.168.42.196:39172] OUTBOUND HEADERS: streamId=3 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, exception-type: org.apache.ratis.protocol.exceptions.ReconfigurationTimeoutException, exception-object-bin: rO0ABXNyAERvcmcuYXBhY2hlLnJhdGlzLnByb3RvY29sLmV4Y2VwdGlvbnMuUmVjb25maWd1cmF0aW9uVGltZW91dEV4Y2VwdGlvbmw90jhgLZ4SAgAAeHIAMm9yZy5hcGFjaGUucmF0aXMucHJvdG9jb2wuZXhjZXB0aW9ucy5SYWZ0RXhjZXB0aW9uAAAAAAAAAAECAAB4cgATamF2YS5pby5JT0V4Y2VwdGlvbmyAc2RlJfCrAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q/R8+GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4ACXQBbDE5Mi4xNjguNDIuMjA0XzQwMDkwQGdyb3VwLTAwMDEwMDAwMDAwQi1Db25maWd1cmF0aW9uU3RhZ2luZ1N0YXRlOiBGYWlsIHRvIHNldCBjb25maWd1cmF0aW9uIFsxOTIuMTY4LjQyLjE2XzQwMDkwfHJwYzoxOTIuMTY4LjQyLjE2OjQwMDkwfGFkbWluOnxjbGllbnQ6fGRhdGFTdHJlYW06fHByaW9yaXR5OjAsIDE5Mi4xNjguNDIuMTk2XzQwMDkwfHJwYzoxOTIuMTY4LjQyLjE5Njo0MDA5MHxhZG1pbjp8Y2xpZW50OnxkYXRhU3RyZWFtOnxwcmlvcml0eTowLCAxOTIuMTY4LjQyLjIwNF80MDA5MHxycGM6MTkyLjE2OC40Mi4yMDQ6NDAwOTB8YWRtaW46fGNsaWVudDp8ZGF0YVN0cmVhbTp8cHJpb3JpdHk6MV0gZHVlIHRvIE5PUFJPR1JFU1N1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAARzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABkwACGZpbGVOYW1lcQB+AAZMAAptZXRob2ROYW1lcQB+AAZ4cAAABEJ0AEZvcmcuYXBhY2hlLnJhdGlzLnNlcnZlci5pbXBsLkxlYWRlclN0YXRlSW1wbCRDb25maWd1cmF0aW9uU3RhZ2luZ1N0YXRldAAUTGVhZGVyU3RhdGVJbXBsLmphdmF0AARmYWlsc3EAfgANAAACwHQALG9yZy5hcGFjaGUucmF0aXMuc2VydmVyLmltcGwuTGVhZGVyU3RhdGVJbXBscQB+ABB0AAxjaGVja1N0YWdpbmdzcQB+AA0AAABfcQB+ABNxAH4AEHQACmFjY2VzcyQ1MDBzcQB+AA0AAAJ8dAA7b3JnLmFwYWNoZS5yYXRpcy5zZXJ2ZXIuaW1wbC5MZWFkZXJTdGF0ZUltcGwkRXZlbnRQcm9jZXNzb3JxAH4AEHQAA3J1bnNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAIeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB+AB94, grpc-status: 13, grpc-message: 192.168.42.204_40090@group-00010000000B-ConfigurationStagingState: Fail to set configuration [192.168.42.16_40090|rpc:192.168.42.16:40090|admin:|client:|dataStream:|priority:0, 192.168.42.196_40090|rpc:192.168.42.196:40090|admin:|client:|dataStream:|priority:0, 192.168.42.204_40090|rpc:192.168.42.204:40090|admin:|client:|dataStream:|priority:1] due to NOPROGRESS] padding=0 endStream=true

然后过了约一分钟，报之前的Broken pipe。由于add peer在16:20:54就失败了，所以不是后面的Broken pipe直接导致的 2022-06-22 16:21:36,824 [ForkJoinPool.commonPool-worker-9] DEBUG o.a.r.g.s.GrpcServerProtocolService$ServerRequestStreamObserver:102 - 192.168.42.204_40090: reply 192.168.42.196_40090<-192.168.42.204_40090#250:OK-t1,SUCCESS,nextIndex=1,followerCommit=0 2022-06-22 16:21:36,824 [grpc-default-worker-ELG-3-3] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x9d090570, L:/192.168.42.204:40090 - R:/192.168.42.196:38776] OUTBOUND DATA: streamId=13 padding=0 endStream=false length=93 bytes=00000000580a450a143139322e3136382e34322e3139365f343030393012143139322e3136382e34322e3230345f34303039301a120a10474747474747474747... 2022-06-22 16:21:36,857 [grpc-default-worker-ELG-3-2] DEBUG o.a.r.t.i.n.u.i.l.AbstractInternalLogger:214 - [id: 0x154a1b7a, L:/192.168.42.204:52562 - R:192.168.42.16/192.168.42.16:50090] OUTBOUND GO_AWAY: lastStreamId=2147483647 errorCode=2 length=48 bytes=7265616441646472657373282e2e29206661696c65643a20436f6e6e656374696f6e2072657365742062792070656572 2022-06-22 16:21:36,859 [grpc-default-worker-ELG-3-2] DEBUG o.a.r.t.i.n.h.c.h.Http2ConnectionHandler:928 - [id: 0x154a1b7a, L:/192.168.42.204:52562 ! R:192.168.42.16/192.168.42.16:50090] Sending GOAWAY failed: lastStreamId '2147483647', errorCode '2', debugData 'readAddress(..) failed: Connection reset by peer'. Forcing shutdown of the connection. org.apache.ratis.thirdparty.io.netty.channel.unix.Errors$NativeIoException: writevAddresses(..) failed: Broken pipe

Jun 22 '22 08:06 BanDuWuZi