Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: Test frozen #679

Open
1 task done
iGxnon opened this issue Mar 7, 2024 · 3 comments
Open
1 task done

[Bug]: Test frozen #679

iGxnon opened this issue Mar 7, 2024 · 3 comments
Labels
bug Something isn't working

Comments

@iGxnon
Copy link
Contributor

iGxnon commented Mar 7, 2024 •
edited
Loading

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

  • I agree to follow this project's Code of Conduct
@iGxnon iGxnon added the bug Something isn't working label Mar 7, 2024
@lxl66566
Copy link
Collaborator

Which test function is this failed test？Or are there multiple failed tests?

@iGxnon
Copy link
Contributor Author

iGxnon commented Jul 30, 2024

Which test function is this failed test？Or are there multiple failed tests?

I'm sorry, I can't remember clearly. According to the description above, it means that all IT incidents have a probability of occurrence.

@lxl66566
Copy link
Collaborator

lxl66566 commented Jul 30, 2024 •
edited
Loading

I'm sorry, I can't remember clearly. According to the description above, it means that all IT incidents have a probability of occurrence.

I executed cargo nextest run for over 100 times, and there's no fail round presented. And this bug looks different to #907. Maybe 100 times is not enough, or maybe this bug has been fixed in some commit.
I think we need at least one reproduction.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@iGxnon @lxl66566