[INFO] fetching crate tender 0.1.1...
[INFO] testing tender-0.1.1 against 1.100.0-beta.1+cargoflags=--release for beta-release-1.100-2
[INFO] extracting crate tender 0.1.1 into /workspace/builds/worker-7-tc2/source
[INFO] started tweaking crates.io crate tender 0.1.1
[INFO] finished tweaking crates.io crate tender 0.1.1
[INFO] tweaked toml for crates.io crate tender 0.1.1 written to /workspace/builds/worker-7-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate tender 0.1.1 on toolchain 1.100.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.100.0-beta.1" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.100.0-beta.1" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]      Locking 34 packages to highest compatible versions
[INFO] [stderr]       Adding env_logger v0.9.3 (available: v0.11.11)
[INFO] [stderr]       Adding fastrand v1.9.0 (available: v2.5.0)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.100.0-beta.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-m" "1610612736" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:77db811e55d90add9212f6832c23229e3de5f1c1f9905e8cb07319ea15df73ac" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b
[INFO] running `Command { std: "docker" "start" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-w" "/opt/rustwide/workdir" "--user" "0:0" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "build" "--frozen" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling smallvec v1.16.3
[INFO] [stderr]    Compiling fastrand v1.9.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.12
[INFO] [stderr]    Compiling parking_lot v0.12.5
[INFO] [stderr]    Compiling sync-wait-group v0.1.1
[INFO] [stderr]    Compiling watch v0.2.3
[INFO] [stderr]    Compiling tender v0.1.1 (/opt/rustwide/workdir)
[INFO] [stdout] warning: variable does not need to be mutable
[INFO] [stdout]   --> src/core/observer.rs:17:16
[INFO] [stdout]    |
[INFO] [stdout] 17 |     pub fn run(mut self) {
[INFO] [stdout]    |                ----^^^^
[INFO] [stdout]    |                |
[INFO] [stdout]    |                help: remove this `mut`
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(unused_mut)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 1.79s
[INFO] running `Command { std: "docker" "inspect" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "test" "--frozen" "--no-run" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling regex-syntax v0.8.11
[INFO] [stderr]    Compiling atty v0.2.14
[INFO] [stderr]    Compiling humantime v2.4.0
[INFO] [stderr]    Compiling tender v0.1.1 (/opt/rustwide/workdir)
[INFO] [stdout] warning: variable does not need to be mutable
[INFO] [stdout]   --> src/core/observer.rs:17:16
[INFO] [stdout]    |
[INFO] [stdout] 17 |     pub fn run(mut self) {
[INFO] [stdout]    |                ----^^^^
[INFO] [stdout]    |                |
[INFO] [stdout]    |                help: remove this `mut`
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(unused_mut)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]    Compiling regex-automata v0.4.18
[INFO] [stderr]    Compiling regex v1.13.1
[INFO] [stderr]    Compiling env_logger v0.9.3
[INFO] [stdout] warning: variable does not need to be mutable
[INFO] [stdout]   --> src/core/observer.rs:17:16
[INFO] [stdout]    |
[INFO] [stdout] 17 |     pub fn run(mut self) {
[INFO] [stdout]    |                ----^^^^
[INFO] [stdout]    |                |
[INFO] [stdout]    |                help: remove this `mut`
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(unused_mut)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 20.88s
[INFO] running `Command { std: "docker" "inspect" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr] warning: variable does not need to be mutable
[INFO] [stderr]   --> src/core/observer.rs:17:16
[INFO] [stderr]    |
[INFO] [stderr] 17 |     pub fn run(mut self) {
[INFO] [stderr]    |                ----^^^^
[INFO] [stderr]    |                |
[INFO] [stderr]    |                help: remove this `mut`
[INFO] [stderr]    |
[INFO] [stderr]    = note: `#[warn(unused_mut)]` (part of `#[warn(unused)]`) on by default
[INFO] [stderr] 
[INFO] [stderr] warning: `tender` (lib) generated 1 warning (run `cargo fix --lib -p tender` to apply 1 suggestion)
[INFO] [stderr] warning: `tender` (lib test) generated 1 warning (1 duplicate)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.05s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/build/tender/87517b42e5bcf482/out/tender-87517b42e5bcf482)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/fixtures.rs (/opt/rustwide/target/release/build/tender/72b4c4bcab75bf64/out/fixtures-72b4c4bcab75bf64)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/group_election.rs (/opt/rustwide/target/release/build/tender/ca50471a8e083d78/out/group_election-ca50471a8e083d78)
[INFO] [stdout] 
[INFO] [stdout] running 6 tests
[INFO] [stdout] test test_election_with_initial_candidate ... ok
[INFO] [stdout] test test_step_up_and_down ... FAILED
[INFO] [stdout] test test_election ... ok
[INFO] [stdout] test test_election_with_quorum ... ok
[INFO] [stdout] test test_move_leader ... ok
[INFO] [stdout] test test_election_with_observer ... ok
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout] 
[INFO] [stdout] ---- test_step_up_and_down stdout ----
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core] [NodeId(1000-1002)][Term(0)] start election main thread
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core::startup] [NodeId(1000-1002)][Term(0)] start the startup loop
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core] [NodeId(1000-1001)][Term(0)] start election main thread
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core::startup] [NodeId(1000-1001)][Term(0)] start the startup loop
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: Startup
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: Startup
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core] [NodeId(1000-1003)][Term(0)] start election main thread
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  tender::core::startup] [NodeId(1000-1003)][Term(0)] start the startup loop
[INFO] [stdout] [2026-10-18T18:42:19Z INFO  group_election::fixtures] [Node(NodeId(1000-1003))] an event has happened: Startup
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::startup] [NodeId(1000-1001)][Term(1)] this node is forced to be leader
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::leader] [NodeId(1000-1001)][Term(1)] start the leader loop
[INFO] [stdout] [2026-10-18T18:42:20Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:20Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:20Z WARN  tender::core::leader] [NodeId(1000-1001)][Term(1)] failed to send heartbeat request to NodeId(1000-1003): RPC error: failed to receive heartbeat response from channel: receiving on an empty and disconnected channel
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::startup] [NodeId(1000-1002)][Term(0)] this node is initialized with 3 members, and transit to follower
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::follower] [NodeId(1000-1002)][Term(0)] start the follower loop
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: TransitToLeader { term: 1, caused_by_step_up: false }
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::startup] [NodeId(1000-1003)][Term(0)] this node is initialized with 3 members, and transit to follower
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core::follower] [NodeId(1000-1003)][Term(0)] start the follower loop
[INFO] [stdout] [2026-10-18T18:42:20Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(0)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  tender::core] [NodeId(1000-1002)][Term(1)] change leader to NodeId(1000-1001)
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })
[INFO] [stdout] [2026-10-18T18:42:20Z DEBUG tender::core::follower] [NodeId(1000-1002)][Term(1)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })) in term 1 is handled
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  group_election::fixtures] [Node(NodeId(1000-1003))] an event has happened: TransitToFollower { term: 0, prev_state: Startup, caused_by_step_down: false }
[INFO] [stdout] [2026-10-18T18:42:20Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: TransitToFollower { term: 0, prev_state: Startup, caused_by_step_down: false }
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(0)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:21Z INFO  tender::core] [NodeId(1000-1003)][Term(1)] change leader to NodeId(1000-1001)
[INFO] [stdout] [2026-10-18T18:42:21Z INFO  group_election::fixtures] [Node(NodeId(1000-1003))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })
[INFO] [stdout] [2026-10-18T18:42:21Z DEBUG tender::core::follower] [NodeId(1000-1003)][Term(1)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })) in term 1 is handled
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:21Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:22Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(1)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election] --- node NodeId(1000-1001) step down to follower
[INFO] [stdout] [2026-10-18T18:42:23Z DEBUG tender::core::leader] [NodeId(1000-1001)][Term(1)] step down to follower
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election] --- node NodeId(1000-1002) step up to leader
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core::follower] [NodeId(1000-1001)][Term(1)] start the follower loop
[INFO] [stdout] [2026-10-18T18:42:23Z DEBUG tender::core::follower] [NodeId(1000-1002)][Term(1)] step up to leader
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core::leader] [NodeId(1000-1002)][Term(1)] start the leader loop
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1002)][Term(1)] send heartbeat to node(NodeId(1000-1001))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::leader] [NodeId(1000-1002)][Term(1)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1002 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core] [NodeId(1000-1003)][Term(1)] change leader from NodeId(1000-1001) to NodeId(1000-1002)
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1003))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1002 })
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: TransitToLeader { term: 1, caused_by_step_up: true }
[INFO] [stdout] [2026-10-18T18:42:23Z TRACE tender::core::follower] [NodeId(1000-1001)][Term(1)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1001 }, leader_id: NodeId { group_id: 1000, group_node_id: 1002 }, term: 1 }
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core] [NodeId(1000-1001)][Term(1)] change leader from NodeId(1000-1001) to NodeId(1000-1002)
[INFO] [stdout] [2026-10-18T18:42:23Z DEBUG tender::core::follower] [NodeId(1000-1003)][Term(1)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1002 })) in term 1 is handled
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: TransitToFollower { term: 1, prev_state: Leader, caused_by_step_down: true }
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core] [NodeId(1000-1002)][Term(1)] change leader from NodeId(1000-1002) to NodeId(1000-1001)
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core] [NodeId(1000-1002)][Term(1)] received valid heartbeat in Leader state, so transit to follower
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  tender::core::follower] [NodeId(1000-1002)][Term(1)] start the follower loop
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })
[INFO] [stderr] error: test failed, to rerun pass `--test group_election`
[INFO] [stdout] [2026-10-18T18:42:23Z DEBUG tender::core::follower] [NodeId(1000-1002)][Term(1)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })) in term 1 is handled
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1002 })
[INFO] [stdout] [2026-10-18T18:42:23Z INFO  group_election::fixtures] [Node(NodeId(1000-1002))] an event has happened: TransitToFollower { term: 1, prev_state: Leader, caused_by_step_down: false }
[INFO] [stdout] [2026-10-18T18:42:23Z DEBUG tender::core::follower] [NodeId(1000-1001)][Term(1)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1002 })) in term 1 is handled
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::follower] [NodeId(1000-1001)][Term(1)] an election timeout is hit, need to transit to pre-candidate
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::candidate] [NodeId(1000-1001)][Term(1)] start the pre-candidate loop
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(1)] quorum is Major, votes granted(1/2)
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(1)] start to send pre-vote request to all nodes(2)
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: TransitToPreCandidate
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core] [NodeId(1000-1003)][Term(1)] voted for pre-candidate(NodeId(1000-1001))
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(1)] received vote response : VoteResponse { node_id: NodeId { group_id: 1000, group_node_id: 1003 }, candidate_id: NodeId { group_id: 1000, group_node_id: 1001 }, vote_id: 1, term: 1, pre_vote: true, vote_result: Granted }
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(1)] votes granted(2/2)
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::candidate] [NodeId(1000-1001)][Term(1)] minimum number of pre-votes have been received, so transit to candidate
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::candidate] [NodeId(1000-1001)][Term(1)] start the candidate loop
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(1)] quorum is Major, votes granted(1/2)
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(2)] start to send vote request to all nodes(2)
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core] [NodeId(1000-1002)][Term(1)] voted for pre-candidate(NodeId(1000-1001))
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core] [NodeId(1000-1002)][Term(2)] vote request term(2) is greater than current term(2)
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core] [NodeId(1000-1002)][Term(2)] granted vote for candidate(NodeId(1000-1001))
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(2)] received vote response : VoteResponse { node_id: NodeId { group_id: 1000, group_node_id: 1002 }, candidate_id: NodeId { group_id: 1000, group_node_id: 1001 }, vote_id: 1, term: 1, pre_vote: true, vote_result: Granted }
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(2)] vote id is 2, so ignore vote response: VoteResponse { node_id: NodeId { group_id: 1000, group_node_id: 1002 }, candidate_id: NodeId { group_id: 1000, group_node_id: 1001 }, vote_id: 1, term: 1, pre_vote: true, vote_result: Granted }
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(2)] received vote response : VoteResponse { node_id: NodeId { group_id: 1000, group_node_id: 1002 }, candidate_id: NodeId { group_id: 1000, group_node_id: 1001 }, vote_id: 2, term: 2, pre_vote: false, vote_result: Granted }
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::candidate] [NodeId(1000-1001)][Term(2)] votes granted(2/2)
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::candidate] [NodeId(1000-1001)][Term(2)] minimum number of votes have been received, so transit to leader
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core::leader] [NodeId(1000-1001)][Term(2)] start the leader loop
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: TransitToLeader { term: 2, caused_by_step_up: false }
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  group_election::fixtures] [Node(NodeId(1000-1001))] an event has happened: TransitToCandidate
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core] [NodeId(1000-1003)][Term(2)] vote request term(2) is greater than current term(2)
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core] [NodeId(1000-1003)][Term(2)] granted vote for candidate(NodeId(1000-1001))
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  tender::core] [NodeId(1000-1003)][Term(2)] change leader from NodeId(1000-1002) to NodeId(1000-1001)
[INFO] [stdout] [2026-10-18T18:42:25Z INFO  group_election::fixtures] [Node(NodeId(1000-1003))] an event has happened: ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })
[INFO] [stdout] [2026-10-18T18:42:25Z DEBUG tender::core::follower] [NodeId(1000-1003)][Term(2)] event (ChangeLeader(NodeId { group_id: 1000, group_node_id: 1001 })) in term 2 is handled
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] [2026-10-18T18:42:25Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] [2026-10-18T18:42:26Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1003))
[INFO] [stdout] [2026-10-18T18:42:26Z TRACE tender::core::leader] [NodeId(1000-1001)][Term(2)] send heartbeat to node(NodeId(1000-1002))
[INFO] [stdout] [2026-10-18T18:42:26Z TRACE tender::core::follower] [NodeId(1000-1002)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1002 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] [2026-10-18T18:42:26Z TRACE tender::core::follower] [NodeId(1000-1003)][Term(2)] received heartbeat: HeartbeatRequest { target_node_id: NodeId { group_id: 1000, group_node_id: 1003 }, leader_id: NodeId { group_id: 1000, group_node_id: 1001 }, term: 2 }
[INFO] [stdout] 
[INFO] [stdout] thread 'test_step_up_and_down' (495) panicked at tests/fixtures.rs:279:9:
[INFO] [stdout] assertion `left == right` failed
[INFO] [stdout]   left: Leader
[INFO] [stdout]  right: Follower
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x5df560e45e31 - <<std[617be2ca0a6fd877]::sys::backtrace::BacktraceLock>::print::DisplayBacktrace as core[a373ad73a504971]::fmt::Display>::fmt
[INFO] [stdout]    1:     0x5df560e5b85a - core[a373ad73a504971]::fmt::write
[INFO] [stdout]    2:     0x5df560e4a3ac - <alloc[2e1b2a31b91974c5]::vec::Vec<u8> as core[a373ad73a504971]::io::write::Write>::write_fmt
[INFO] [stdout]    3:     0x5df560e21ea6 - std[617be2ca0a6fd877]::panicking::default_hook::{closure#0}
[INFO] [stdout]    4:     0x5df560e3e119 - std[617be2ca0a6fd877]::panicking::default_hook
[INFO] [stdout]    5:     0x5df560dd56b0 - test[aada8e7e76ba119b]::test_main_inner::{closure#0}
[INFO] [stdout]    6:     0x5df560e3e2d2 - std[617be2ca0a6fd877]::panicking::panic_with_hook
[INFO] [stdout]    7:     0x5df560e21f52 - std[617be2ca0a6fd877]::panicking::panic_handler::{closure#0}
[INFO] [stdout]    8:     0x5df560e1ac39 - std[617be2ca0a6fd877]::sys::backtrace::__rust_end_short_backtrace::<std[617be2ca0a6fd877]::panicking::panic_handler::{closure#0}, !>
[INFO] [stdout]    9:     0x5df560e22b5d - __rustc[ea4f61d10b84890b]::rust_begin_unwind
[INFO] [stdout]   10:     0x5df560e5c03c - core[a373ad73a504971]::panicking::panic_fmt
[INFO] [stdout]   11:     0x5df560e5bf53 - core[a373ad73a504971]::panicking::assert_failed_inner
[INFO] [stdout]   12:     0x5df560cee4a4 - core[a373ad73a504971]::panicking::assert_failed::<tender[ca7140d40acaffa2]::core::State, tender[ca7140d40acaffa2]::core::State>
[INFO] [stdout]   13:     0x5df560cc9e1e - <group_election[e628d5efac512b99]::fixtures::MemRouter>::assert_node_state
[INFO] [stdout]   14:     0x5df560cf01ab - <group_election[e628d5efac512b99]::test_step_up_and_down::{closure#0} as core[a373ad73a504971]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]   15:     0x5df560dc8afb - test[aada8e7e76ba119b]::__rust_begin_short_backtrace::<core[a373ad73a504971]::result::Result<(), alloc[2e1b2a31b91974c5]::string::String>, fn() -> core[a373ad73a504971]::result::Result<(), alloc[2e1b2a31b91974c5]::string::String>>
[INFO] [stdout]   16:     0x5df560dd5cd5 - test[aada8e7e76ba119b]::run_test::{closure#0}
[INFO] [stdout]   17:     0x5df560dcf5c4 - std[617be2ca0a6fd877]::sys::backtrace::__rust_begin_short_backtrace::<test[aada8e7e76ba119b]::run_test::{closure#1}, ()>
[INFO] [stdout]   18:     0x5df560dd8d62 - <std[617be2ca0a6fd877]::thread::lifecycle::spawn_unchecked<test[aada8e7e76ba119b]::run_test::{closure#1}, ()>::{closure#1} as core[a373ad73a504971]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
[INFO] [stdout]   19:     0x5df560e4565f - <std[617be2ca0a6fd877]::sys::thread::unix::Thread>::new::thread_start
[INFO] [stdout]   20:     0x7873f08fcdfa - <unknown>
[INFO] [stdout]   21:     0x7873f09903d4 - clone
[INFO] [stdout]   22:                0x0 - <unknown>
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout]     test_step_up_and_down
[INFO] [stdout] 
[INFO] [stdout] test result: FAILED. 5 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 10.02s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b", kill_on_drop: false }`
[INFO] [stdout] e33fd7a549dfee2040bad0370ff0ae780f1d34cd7dc3f856d209f665c5f8977b
