Xline
Xline copied to clipboard
Published
20 hours ago •
xline-kv
xline-kv
[Bug]: Test frozen
Description about the bug
The integration testing of the xline and xline-client crates may hang and cannot continue. It seems to be a deadlock issue.
Version
0.6.1 (Default)
Relevant log output
running 1 test
0.004294484s INFO xline::server::xline_server: name = "server0"
0.004331983s INFO xline::server::xline_server: cluster_peers = {"server1": ["0.0.0.0:36567"], "server2": ["0.0.0.0:42925"], "server0": ["0.0.0.0:43103"]}
0.004375002s INFO xline::server::xline_server: get cluster_info by args
0.005196387s DEBUG curp::server::raw_curp: 3509270774065777449 becomes the leader
0.005308692s DEBUG curp::server::curp_node: 3509270774065777449 to 13847607617504644160 sync follower task start
0.005329143s DEBUG curp::server::curp_node: 3509270774065777449 to 13798247851104566989 sync follower task start
0.005341701s DEBUG curp::client::state: client bypassed server(3509270774065777449)
0.005491779s DEBUG curp::client::stream: cannot find the leader id in state, wait for leadership update
0.005781815s DEBUG curp::client::unary: fetch local cluster FetchClusterResponse { leader_id: Some(3509270774065777449), term: 1, cluster_id: 6126940540364633460, members: [Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: ["0.0.0.0:42687"], is_learner: false }, Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: [], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: [], is_learner: false }], cluster_version: 0 }
0.005839624s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets publish with propose id 0#17456405612003375492
0.005882571s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets new log[1]
0.005931846s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 17456405612003375492), entry_data: SetNodeState(3509270774065777449, "server0", ["0.0.0.0:42687"]) })
0.006011238s INFO xline::server::xline_server: name = "server1"
0.006027337s INFO xline::server::xline_server: cluster_peers = {"server1": ["0.0.0.0:36567"], "server0": ["0.0.0.0:43103"], "server2": ["0.0.0.0:42925"]}
0.006051485s INFO xline::server::xline_server: get cluster_info by args
0.006501194s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.006503847s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13798247851104566989
0.006562321s DEBUG curp::server::curp_node: 13798247851104566989 to 13847607617504644160 sync follower task start
0.006580649s DEBUG curp::server::curp_node: 13798247851104566989 to 3509270774065777449 sync follower task start
0.006577188s DEBUG curp::client::state: client bypassed server(13798247851104566989)
0.006677971s DEBUG curp::client::stream: cannot find the leader id in state, wait for leadership update
0.006879163s DEBUG curp::client::unary: fetch local cluster FetchClusterResponse { leader_id: None, term: 0, cluster_id: 6126940540364633460, members: [Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: [], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: ["0.0.0.0:41537"], is_learner: false }, Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: [], is_learner: false }], cluster_version: 0 }
0.006906488s DEBUG curp::client: no leader id in FetchClusterResponse, try to send linearizable request
0.006978775s DEBUG curp::client::unary: fetch cluster from 13798247851104566989 success
0.007958839s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 received append_entries from 3509270774065777449: term(1), commit(0), prev_log_index(0), prev_log_term(0), 1 entries
0.008009710s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 updates to term 1 and becomes a follower
0.051878047s DEBUG curp::client::unary: fetch cluster from 3509270774065777449 success
0.051974051s DEBUG curp::server::raw_curp::state: follower 13798247851104566989's match_index updated to 1
0.052048731s DEBUG curp::server::raw_curp: 3509270774065777449 updates commit index to 1
0.052095998s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[1], last_applied updated to 1
0.052153251s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 17456405612003375492), entry_data: SetNodeState(3509270774065777449, "server0", ["0.0.0.0:42687"]) })
0.052272873s DEBUG curp::members: set name and client_urls for node 3509270774065777449 to server0,["0.0.0.0:42687"]
0.057379031s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.073112012s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.124725764s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.140710670s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.191845842s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.207752357s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.258689963s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.274842913s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.307374954s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[1], last_applied updated to 1
0.307529915s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 17456405612003375492), entry_data: SetNodeState(3509270774065777449, "server0", ["0.0.0.0:42687"]) })
0.307637660s DEBUG curp::members: set name and client_urls for node 3509270774065777449 to server0,["0.0.0.0:42687"]
0.325389583s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.325513116s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.376385636s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.392932663s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.444609186s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.460352606s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.511341434s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.527826054s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.578531418s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.595321508s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.647074249s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.647152099s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.699160997s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.715934996s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.766776090s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.782552659s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.833355873s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.850276587s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.902033606s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.918586891s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
0.969918789s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
0.969995066s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.021560671s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.037310585s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.088369701s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.104955646s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.156806414s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.172495565s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.223636416s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.239218918s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.291030860s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.291083069s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.342343644s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.359004613s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.410542692s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.426840534s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.477746146s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.493618674s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.544744926s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.560194262s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.611985992s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.612044359s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.663551687s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.680192508s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.732028890s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.748478972s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.800184929s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.816519640s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.867770769s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.883409080s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.935094833s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
1.935145270s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
1.986991841s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.002732615s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.008344091s WARN curp::client::unary: fetch cluster from 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.008395366s WARN curp::client::retry: got error: Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }"), retry on 1.5 seconds later
2.053910349s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.069677060s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.120522908s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.137009621s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.188467917s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.204722704s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.255530342s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.255604872s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.307066977s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.323775951s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.374455614s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.391147007s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.442717014s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.458253357s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.509671686s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.525355683s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.576404305s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.576500712s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.627331045s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.643897355s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.695342857s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.711868948s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.762247645s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.778822828s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.829211614s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.845771041s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.896380459s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.896442313s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
2.947817657s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
2.963362692s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.014527024s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.031414862s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.083111593s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.099639249s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.150934986s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.166630578s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.217513258s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.217578713s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.269118444s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.285723055s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.336501459s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.353149210s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.405004751s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.420323300s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.471241514s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
3.487767752s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.509823411s DEBUG curp::client::unary: fetch local cluster FetchClusterResponse { leader_id: Some(3509270774065777449), term: 1, cluster_id: 6126940540364633460, members: [Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: ["0.0.0.0:42687"], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: ["0.0.0.0:41537"], is_learner: false }, Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: [], is_learner: false }], cluster_version: 0 }
3.510602849s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets publish with propose id 0#13844113600505119605
3.510653711s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets new log[2]
3.510848268s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 13844113600505119605), entry_data: SetNodeState(13798247851104566989, "server1", ["0.0.0.0:41537"]) })
3.511294881s INFO xline::server::xline_server: name = "server2"
3.511323245s INFO xline::server::xline_server: cluster_peers = {"server1": ["0.0.0.0:36567"], "server0": ["0.0.0.0:43103"], "server2": ["0.0.0.0:42925"]}
3.511358152s INFO xline::server::xline_server: get cluster_info by args
3.512004736s DEBUG curp::client::state: client bypassed server(13847607617504644160)
3.512032017s DEBUG curp::server::curp_node: 13847607617504644160 to 3509270774065777449 sync follower task start
3.512040329s DEBUG curp::server::curp_node: 13847607617504644160 to 13798247851104566989 sync follower task start
3.512143676s DEBUG curp::client::stream: cannot find the leader id in state, wait for leadership update
3.512334435s DEBUG curp::client::unary: fetch local cluster FetchClusterResponse { leader_id: None, term: 0, cluster_id: 6126940540364633460, members: [Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: ["0.0.0.0:44103"], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: [], is_learner: false }, Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: [], is_learner: false }], cluster_version: 0 }
3.512365855s DEBUG curp::client: no leader id in FetchClusterResponse, try to send linearizable request
3.512402724s DEBUG curp::client::unary: fetch cluster from 13847607617504644160 success
3.514081297s DEBUG curp::client::unary: fetch cluster from 13798247851104566989 success
3.514164077s DEBUG curp::client::unary: fetch cluster succeeded, result: FetchClusterResponse { leader_id: Some(3509270774065777449), term: 1, cluster_id: 6126940540364633460, members: [Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: ["0.0.0.0:42687"], is_learner: false }, Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: [], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: [], is_learner: false }], cluster_version: 0 }
3.514189177s INFO curp::client::state: client term updates to 1, client leader id updates to 3509270774065777449
3.514209309s DEBUG curp::client::state: ignore cluster version(0) from server
3.514233278s DEBUG curp::client::stream: interrupt keep heartbeat because leadership changed
3.514916354s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets publish with propose id 0#16755041282598021439
3.514951927s DEBUG curp_publish: curp::server::raw_curp: 3509270774065777449 gets new log[3]
3.515130929s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(0, 16755041282598021439), entry_data: SetNodeState(13847607617504644160, "server2", ["0.0.0.0:44103"]) })
3.515227266s DEBUG curp::rpc::connect: client request a client id
3.515670435s INFO curp::rpc::connect: client_id update to 8955998196852596353
3.516217716s DEBUG curp::rpc::connect: client keep alive the client id(8955998196852596353)
3.516367550s WARN curp::server::curp_node: ae to 13847607617504644160 failed, Internal("status: ResourceExhausted, message: \"h2 protocol error: http2 error: connection error received: detected excessive load generating behavior (b\\\"too_many_resets\\\")\", details: [], metadata: MetadataMap { headers: {} }")
3.517515836s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13798247851104566989
3.518074599s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 received append_entries from 3509270774065777449: term(1), commit(1), prev_log_index(1), prev_log_term(1), 2 entries
3.518240623s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.518422941s DEBUG curp::server::raw_curp::state: follower 13798247851104566989's match_index updated to 3
3.518485747s DEBUG curp::server::raw_curp: 3509270774065777449 updates commit index to 3
3.518510048s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[2], last_applied updated to 2
3.518526252s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[3], last_applied updated to 3
3.518556113s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 13844113600505119605), entry_data: SetNodeState(13798247851104566989, "server1", ["0.0.0.0:41537"]) })
3.518574504s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(0, 16755041282598021439), entry_data: SetNodeState(13847607617504644160, "server2", ["0.0.0.0:44103"]) })
3.518614298s DEBUG curp::members: set name and client_urls for node 13798247851104566989 to server1,["0.0.0.0:41537"]
3.518702483s DEBUG curp::members: set name and client_urls for node 13847607617504644160 to server2,["0.0.0.0:44103"]
3.519082995s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 received append_entries from 3509270774065777449: term(1), commit(1), prev_log_index(0), prev_log_term(0), 3 entries
3.519132474s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 updates to term 1 and becomes a follower
3.519175735s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[1], last_applied updated to 1
3.519296495s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 17456405612003375492), entry_data: SetNodeState(3509270774065777449, "server0", ["0.0.0.0:42687"]) })
3.519419354s DEBUG curp::members: set name and client_urls for node 3509270774065777449 to server0,["0.0.0.0:42687"]
3.519587829s DEBUG curp::server::raw_curp::state: follower 13847607617504644160's match_index updated to 3
3.607408604s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[2], last_applied updated to 2
3.607446993s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[3], last_applied updated to 3
3.607611453s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 13844113600505119605), entry_data: SetNodeState(13798247851104566989, "server1", ["0.0.0.0:41537"]) })
3.607652075s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(0, 16755041282598021439), entry_data: SetNodeState(13847607617504644160, "server2", ["0.0.0.0:44103"]) })
3.607702810s DEBUG curp::members: set name and client_urls for node 13798247851104566989 to server1,["0.0.0.0:41537"]
3.607764779s DEBUG curp::members: set name and client_urls for node 13847607617504644160 to server2,["0.0.0.0:44103"]
3.818912459s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[2], last_applied updated to 2
3.818954597s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[3], last_applied updated to 3
3.819150145s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 13844113600505119605), entry_data: SetNodeState(13798247851104566989, "server1", ["0.0.0.0:41537"]) })
3.819191186s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(0, 16755041282598021439), entry_data: SetNodeState(13847607617504644160, "server2", ["0.0.0.0:44103"]) })
3.819212636s DEBUG curp::rpc::connect: client request a client id
3.819254336s DEBUG curp::members: set name and client_urls for node 13798247851104566989 to server1,["0.0.0.0:41537"]
3.819288870s DEBUG curp::members: set name and client_urls for node 13847607617504644160 to server2,["0.0.0.0:44103"]
3.819471493s DEBUG xline::server::auth_wrapper: AuthWrapper received propose request: 0#13040520054810735106
3.819564059s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets proposal for cmd(0#13040520054810735106)
3.819601182s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#13040520054810735106) into spec pool
3.819642220s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets new log[4]
3.819647498s DEBUG xline::server::auth_wrapper: AuthWrapper received propose request: 0#13040520054810735106
3.819702851s DEBUG curp_propose: curp::server::raw_curp: 13847607617504644160 gets proposal for cmd(0#13040520054810735106)
3.819733799s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#13040520054810735106) into spec pool
3.819747780s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(0, 13040520054810735106), entry_data: Command(Command { request: LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }), keys: [], compact_id: 0, auth_info: None }) })
3.819783943s DEBUG xline::storage::lease_store: Receive request LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 })
3.819789491s DEBUG xline::storage::lease_store: Receive LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.819830303s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(0#13040520054810735106) is speculatively executed, exe status: true
3.819885620s DEBUG curp_wait_synced: curp::server::curp_node: 3509270774065777449 get wait synced request for cmd(0#13040520054810735106)
3.819931900s INFO curp::rpc::connect: client_id update to 10409437774952048781
3.820133785s DEBUG curp::rpc::connect: client keep alive the client id(10409437774952048781)
3.832740436s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13798247851104566989
3.833367600s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 received append_entries from 3509270774065777449: term(1), commit(3), prev_log_index(3), prev_log_term(1), 1 entries
3.833696402s DEBUG curp::server::raw_curp::state: follower 13798247851104566989's match_index updated to 4
3.833759642s DEBUG curp::server::raw_curp: 3509270774065777449 updates commit index to 4
3.833797339s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[4], last_applied updated to 4
3.833836995s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(0, 13040520054810735106), entry_data: Command(Command { request: LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }), keys: [], compact_id: 0, auth_info: None }) })
3.833881892s DEBUG xline::storage::lease_store: Sync LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.833964469s DEBUG curp::server::spec_pool: cmd(0#13040520054810735106) is removed from spec pool
3.833988703s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(0#13040520054810735106) after sync is called
3.834060808s DEBUG curp_wait_synced: curp::server::curp_node: 3509270774065777449 wait synced for cmd(0#13040520054810735106) finishes
3.834624023s DEBUG curp::client::unary: slow round for cmd(0#13040520054810735106) succeed
3.835189720s DEBUG xline::server::auth_wrapper: AuthWrapper received propose request: 10409437774952048781#10571598307564506196
3.835199535s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.835270544s DEBUG curp_propose: curp::server::raw_curp: 13847607617504644160 gets proposal for cmd(10409437774952048781#10571598307564506196)
3.835500455s DEBUG xline::server::auth_wrapper: AuthWrapper received propose request: 10409437774952048781#10571598307564506196
3.835501247s DEBUG curp_wait_synced: curp::server::curp_node: 3509270774065777449 get wait synced request for cmd(10409437774952048781#10571598307564506196)
3.835585815s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets proposal for cmd(10409437774952048781#10571598307564506196)
3.835613672s DEBUG curp_propose: curp::server::spec_pool: insert cmd(10409437774952048781#10571598307564506196) into spec pool
3.835657844s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets new log[5]
3.835718864s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 received append_entries from 3509270774065777449: term(1), commit(4), prev_log_index(3), prev_log_term(1), 1 entries
3.835774472s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[4], last_applied updated to 4
3.835785545s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(10409437774952048781, 10571598307564506196), entry_data: Command(Command { request: TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }], compact_id: 0, auth_info: None }) })
3.835828610s WARN curp::client::unary: propose cmd(10409437774952048781#10571598307564506196) to server(13847607617504644160) error: KeyConflict(())
3.835840145s DEBUG xline::storage::kv_store: Execute TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] })
3.835878389s DEBUG xline::storage::kv_store: Execute PutRequest(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })
3.835888215s DEBUG xline::storage::kv_store: Execute RangeRequest(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })
3.835886800s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(0, 13040520054810735106), entry_data: Command(Command { request: LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }), keys: [], compact_id: 0, auth_info: None }) })
3.835928191s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(10409437774952048781#10571598307564506196) is speculatively executed, exe status: true
3.835953426s DEBUG xline::storage::lease_store: Receive request LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 })
3.835961871s DEBUG xline::storage::lease_store: Receive LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.835986597s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(0#13040520054810735106) is speculatively executed, exe status: true
3.836014705s DEBUG xline::storage::lease_store: Sync LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.836045783s DEBUG curp::server::spec_pool: cmd(0#13040520054810735106) is removed from spec pool
3.836060909s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(0#13040520054810735106) after sync is called
3.836408021s DEBUG curp::server::raw_curp::state: follower 13847607617504644160's match_index updated to 4
3.849790398s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13798247851104566989
3.850451097s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 received append_entries from 3509270774065777449: term(1), commit(4), prev_log_index(4), prev_log_term(1), 1 entries
3.850527121s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[4], last_applied updated to 4
3.850654672s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(0, 13040520054810735106), entry_data: Command(Command { request: LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }), keys: [], compact_id: 0, auth_info: None }) })
3.850711456s DEBUG xline::storage::lease_store: Receive request LeaseGrantRequest(LeaseGrantRequest { ttl: 1, id: 8594769310087548870 })
3.850730295s DEBUG xline::storage::lease_store: Receive LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.850754764s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(0#13040520054810735106) is speculatively executed, exe status: true
3.850789302s DEBUG xline::storage::lease_store: Sync LeaseGrantRequest LeaseGrantRequest { ttl: 1, id: 8594769310087548870 }
3.850848786s DEBUG curp::server::spec_pool: cmd(0#13040520054810735106) is not in spec pool
3.850864570s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(0#13040520054810735106) after sync is called
3.850939255s DEBUG curp::server::raw_curp::state: follower 13798247851104566989's match_index updated to 5
3.851038417s DEBUG curp::server::raw_curp: 3509270774065777449 updates commit index to 5
3.851072358s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[5], last_applied updated to 5
3.851110548s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(10409437774952048781, 10571598307564506196), entry_data: Command(Command { request: TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }], compact_id: 0, auth_info: None }) })
3.851179578s DEBUG xline::storage::kv_store: After Sync TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }) with revision 2
3.851311720s DEBUG curp::server::spec_pool: cmd(10409437774952048781#10571598307564506196) is removed from spec pool
3.851327372s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(10409437774952048781#10571598307564506196) after sync is called
3.851388753s DEBUG curp_wait_synced: curp::server::curp_node: 3509270774065777449 wait synced for cmd(10409437774952048781#10571598307564506196) finishes
3.852526694s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
3.853124828s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 received append_entries from 3509270774065777449: term(1), commit(5), prev_log_index(4), prev_log_term(1), 1 entries
3.853204706s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[5], last_applied updated to 5
3.853308432s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(10409437774952048781, 10571598307564506196), entry_data: Command(Command { request: TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }], compact_id: 0, auth_info: None }) })
3.853365627s DEBUG xline::storage::kv_store: Execute TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] })
3.853405573s DEBUG xline::storage::kv_store: Execute PutRequest(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })
3.853427051s DEBUG xline::storage::kv_store: Execute RangeRequest(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })
3.853445833s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(10409437774952048781#10571598307564506196) is speculatively executed, exe status: true
3.853480627s DEBUG xline::storage::kv_store: After Sync TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }) with revision 2
3.853500876s DEBUG curp::server::raw_curp::state: follower 13847607617504644160's match_index updated to 5
3.853561987s DEBUG curp::server::spec_pool: cmd(10409437774952048781#10571598307564506196) is not in spec pool
3.853578124s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(10409437774952048781#10571598307564506196) after sync is called
3.881769462s DEBUG curp::client::unary: slow round for cmd(10409437774952048781#10571598307564506196) succeed
3.907617305s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[5], last_applied updated to 5
3.907878073s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(10409437774952048781, 10571598307564506196), entry_data: Command(Command { request: TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }, KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }, KeyRange { key: Included([116, 101, 115, 116, 47]), range_end: Excluded([116, 101, 115, 116, 48]) }], compact_id: 0, auth_info: None }) })
3.907982472s DEBUG xline::storage::kv_store: Execute TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] })
3.908050553s DEBUG xline::storage::kv_store: Execute PutRequest(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })
3.908078140s DEBUG xline::storage::kv_store: Execute RangeRequest(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })
3.908118450s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(10409437774952048781#10571598307564506196) is speculatively executed, exe status: true
3.908166745s DEBUG xline::storage::kv_store: After Sync TxnRequest(TxnRequest { compare: [Compare { result: Equal, target: Create, key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], target_union: Some(CreateRevision(0)) }], success: [RequestOp { request: Some(RequestPut(PutRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], value: [], lease: 8594769310087548870, prev_kv: false, ignore_value: false, ignore_lease: false })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }], failure: [RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54], range_end: [], limit: 0, revision: 0, sort_order: None, sort_target: Key, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }, RequestOp { request: Some(RequestRange(RangeRequest { key: [116, 101, 115, 116, 47], range_end: [116, 101, 115, 116, 48], limit: 1, revision: 0, sort_order: Ascend, sort_target: Create, serializable: false, keys_only: false, count_only: false, min_mod_revision: 0, max_mod_revision: 0, min_create_revision: 0, max_create_revision: 0 })) }] }) with revision 2
3.908283848s DEBUG curp::server::spec_pool: cmd(10409437774952048781#10571598307564506196) is not in spec pool
3.908301204s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(10409437774952048781#10571598307564506196) after sync is called
4.516122418s DEBUG curp::rpc::connect: client keep alive the client id(8955998196852596353)
4.820944585s DEBUG curp::rpc::connect: client keep alive the client id(10409437774952048781)
5.016164028s DEBUG xline::server::lease_server: Receive LeaseRevokeRequest Request { metadata: MetadataMap { headers: {} }, message: LeaseRevokeRequest { id: 8594769310087548870 }, extensions: Extensions }
5.016418554s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets proposal for cmd(0#1340017117991781026)
5.016452809s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#1340017117991781026) into spec pool
5.016506796s DEBUG curp_propose: curp::server::raw_curp: 3509270774065777449 gets new log[6]
5.016706551s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 6, propose_id: ProposeId(0, 1340017117991781026), entry_data: Command(Command { request: LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }], compact_id: 0, auth_info: None }) })
5.016737075s DEBUG curp::client::unary: fetch local cluster FetchClusterResponse { leader_id: Some(3509270774065777449), term: 1, cluster_id: 6126940540364633460, members: [Member { id: 3509270774065777449, name: "server0", peer_urls: ["0.0.0.0:43103"], client_urls: ["0.0.0.0:42687"], is_learner: false }, Member { id: 13847607617504644160, name: "server2", peer_urls: ["0.0.0.0:42925"], client_urls: ["0.0.0.0:44103"], is_learner: false }, Member { id: 13798247851104566989, name: "server1", peer_urls: ["0.0.0.0:36567"], client_urls: ["0.0.0.0:41537"], is_learner: false }], cluster_version: 0 }
5.016765701s DEBUG curp_wait_synced: curp::server::curp_node: 3509270774065777449 get wait synced request for cmd(0#1340017117991781026)
5.016772461s DEBUG xline::storage::lease_store: Receive request LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 })
5.016811371s DEBUG xline::storage::lease_store: Receive LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.016842000s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(0#1340017117991781026) is speculatively executed, exe status: true
5.017646227s DEBUG curp_propose: curp::server::raw_curp: 13847607617504644160 gets proposal for cmd(0#1340017117991781026)
5.017646778s DEBUG curp_propose: curp::server::raw_curp: 13798247851104566989 gets proposal for cmd(0#1340017117991781026)
5.017689324s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#1340017117991781026) into spec pool
5.017722150s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#1340017117991781026) into spec pool
5.018223395s DEBUG curp::client::unary: fast round for cmd(0#1340017117991781026) succeed
5.018305632s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13847607617504644160
5.018316024s DEBUG curp::server::curp_node: 3509270774065777449 send append_entries to 13798247851104566989
5.018831368s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 received append_entries from 3509270774065777449: term(1), commit(5), prev_log_index(5), prev_log_term(1), 1 entries
5.018836349s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 received append_entries from 3509270774065777449: term(1), commit(5), prev_log_index(5), prev_log_term(1), 1 entries
5.019220505s DEBUG curp::server::raw_curp::state: follower 13798247851104566989's match_index updated to 6
5.019247372s DEBUG curp::server::raw_curp::state: follower 13847607617504644160's match_index updated to 6
5.019316940s DEBUG curp::server::raw_curp: 3509270774065777449 updates commit index to 6
5.019350756s DEBUG curp::server::raw_curp: 3509270774065777449 committed log[6], last_applied updated to 6
5.019401063s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 6, propose_id: ProposeId(0, 1340017117991781026), entry_data: Command(Command { request: LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }], compact_id: 0, auth_info: None }) })
5.019454965s DEBUG xline::storage::lease_store: Sync LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.019545729s DEBUG curp::server::spec_pool: cmd(0#1340017117991781026) is removed from spec pool
5.019563526s DEBUG curp::server::cmd_worker: 3509270774065777449 cmd(0#1340017117991781026) after sync is called
5.108027910s DEBUG curp_append_entries: curp::server::raw_curp: 13798247851104566989 committed log[6], last_applied updated to 6
5.108297258s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 6, propose_id: ProposeId(0, 1340017117991781026), entry_data: Command(Command { request: LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }], compact_id: 0, auth_info: None }) })
5.108436161s DEBUG xline::storage::lease_store: Receive request LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 })
5.108478317s DEBUG xline::storage::lease_store: Receive LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.108539496s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(0#1340017117991781026) is speculatively executed, exe status: true
5.108617135s DEBUG xline::storage::lease_store: Sync LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.108773371s DEBUG curp::server::spec_pool: cmd(0#1340017117991781026) is removed from spec pool
5.108792695s DEBUG curp::server::cmd_worker: 13798247851104566989 cmd(0#1340017117991781026) after sync is called
5.319614202s DEBUG curp_append_entries: curp::server::raw_curp: 13847607617504644160 committed log[6], last_applied updated to 6
5.319785357s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 6, propose_id: ProposeId(0, 1340017117991781026), entry_data: Command(Command { request: LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 }), keys: [KeyRange { key: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]), range_end: Included([116, 101, 115, 116, 47, 55, 55, 52, 54, 99, 49, 50, 54, 56, 54, 51, 50, 56, 102, 99, 54]) }], compact_id: 0, auth_info: None }) })
5.319856388s DEBUG xline::storage::lease_store: Receive request LeaseRevokeRequest(LeaseRevokeRequest { id: 8594769310087548870 })
5.319874806s DEBUG xline::storage::lease_store: Receive LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.319895488s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(0#1340017117991781026) is speculatively executed, exe status: true
5.319930509s DEBUG xline::storage::lease_store: Sync LeaseRevokeRequest LeaseRevokeRequest { id: 8594769310087548870 }
5.320057063s DEBUG curp::server::spec_pool: cmd(0#1340017117991781026) is removed from spec pool
5.320078188s DEBUG curp::server::cmd_worker: 13847607617504644160 cmd(0#1340017117991781026) after sync is called
5.516960448s DEBUG curp::rpc::connect: client keep alive the client id(8955998196852596353)
5.821005024s DEBUG curp::rpc::connect: client keep alive the client id(10409437774952048781)
6.517131162s DEBUG curp::rpc::connect: client keep alive the client id(8955998196852596353)
6.820860335s DEBUG curp::rpc::connect: client keep alive the client id(10409437774952048781)
... until timeout (30s)
Code of Conduct
- [X] I agree to follow this project's Code of Conduct
