[INFO] cloning repository https://github.com/tomas-rampas/raft-consensus-poc
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/tomas-rampas/raft-consensus-poc" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Ftomas-rampas%2Fraft-consensus-poc", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Ftomas-rampas%2Fraft-consensus-poc'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 4579047e815845c9493133ba0b6b4f46c54bb8d5
[INFO] testing tomas-rampas/raft-consensus-poc against master#c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38 for pr-146098-7
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Ftomas-rampas%2Fraft-consensus-poc" "/workspace/builds/worker-2-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/tomas-rampas/raft-consensus-poc
[INFO] finished tweaking git repo https://github.com/tomas-rampas/raft-consensus-poc
[INFO] tweaked toml for git repo https://github.com/tomas-rampas/raft-consensus-poc written to /workspace/builds/worker-2-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/tomas-rampas/raft-consensus-poc on toolchain c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/tomas-rampas/raft-consensus-poc already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded tungstenite v0.20.1
[INFO] [stderr]   Downloaded tokio-tungstenite v0.20.1
[INFO] [stderr]   Downloaded headers-core v0.2.0
[INFO] [stderr]   Downloaded headers v0.3.9
[INFO] [stderr]   Downloaded warp v0.3.7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 2a2591fc39b7ca275f97fca88c9de402a746754213f619aaa4a98e5512c817ba
[INFO] running `Command { std: "docker" "start" "-a" "2a2591fc39b7ca275f97fca88c9de402a746754213f619aaa4a98e5512c817ba", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "2a2591fc39b7ca275f97fca88c9de402a746754213f619aaa4a98e5512c817ba", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2a2591fc39b7ca275f97fca88c9de402a746754213f619aaa4a98e5512c817ba", kill_on_drop: false }`
[INFO] [stdout] 2a2591fc39b7ca275f97fca88c9de402a746754213f619aaa4a98e5512c817ba
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] b9072ed4b198867b4876b007475f60011b6b48e01b7cd2de438a3071add8b2b6
[INFO] running `Command { std: "docker" "start" "-a" "b9072ed4b198867b4876b007475f60011b6b48e01b7cd2de438a3071add8b2b6", kill_on_drop: false }`
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling version_check v0.9.5
[INFO] [stderr]    Compiling typenum v1.18.0
[INFO] [stderr]    Compiling http v0.2.12
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling signal-hook-registry v1.4.6
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling cpufeatures v0.2.17
[INFO] [stderr]    Compiling tracing-core v0.1.34
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling thiserror-impl v1.0.69
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling tracing-attributes v0.1.30
[INFO] [stderr]    Compiling data-encoding v2.9.0
[INFO] [stderr]    Compiling utf-8 v0.7.6
[INFO] [stderr]    Compiling zerovec v0.11.3
[INFO] [stderr]    Compiling byteorder v1.5.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.11
[INFO] [stderr]    Compiling regex-syntax v0.6.29
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling generic-array v0.14.7
[INFO] [stderr]    Compiling parking_lot v0.12.4
[INFO] [stderr]    Compiling multer v2.1.0
[INFO] [stderr]    Compiling regex-syntax v0.8.5
[INFO] [stderr]    Compiling memchr v2.7.5
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling serde_json v1.0.142
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling tokio v1.47.1
[INFO] [stderr]    Compiling pin-project-internal v1.1.10
[INFO] [stderr]    Compiling socket2 v0.5.10
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling tinystr v0.8.1
[INFO] [stderr]    Compiling potential_utf v0.1.2
[INFO] [stderr]    Compiling icu_collections v2.0.0
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling spin v0.9.8
[INFO] [stderr]    Compiling icu_locale_core v2.0.0
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling base64 v0.21.7
[INFO] [stderr]    Compiling http-body v0.4.6
[INFO] [stderr]    Compiling headers-core v0.2.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling scoped-tls v1.0.1
[INFO] [stderr]    Compiling pin-project v1.1.10
[INFO] [stderr]    Compiling regex-automata v0.1.10
[INFO] [stderr]    Compiling crypto-common v0.1.6
[INFO] [stderr]    Compiling block-buffer v0.10.4
[INFO] [stderr]    Compiling icu_provider v2.0.0
[INFO] [stderr]    Compiling digest v0.10.7
[INFO] [stderr]    Compiling sha1 v0.10.6
[INFO] [stderr]    Compiling icu_normalizer v2.0.0
[INFO] [stderr]    Compiling icu_properties v2.0.1
[INFO] [stderr]    Compiling headers v0.3.9
[INFO] [stderr]    Compiling matchers v0.1.0
[INFO] [stderr]    Compiling regex v1.11.1
[INFO] [stderr]    Compiling idna_adapter v1.2.1
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling chrono v0.4.41
[INFO] [stderr]    Compiling tungstenite v0.21.0
[INFO] [stderr]    Compiling tungstenite v0.20.1
[INFO] [stderr]    Compiling tokio-util v0.7.16
[INFO] [stderr]    Compiling tokio-tungstenite v0.21.0
[INFO] [stderr]    Compiling tokio-tungstenite v0.20.1
[INFO] [stderr]    Compiling h2 v0.3.27
[INFO] [stderr]    Compiling hyper v0.14.32
[INFO] [stderr]    Compiling warp v0.3.7
[INFO] [stderr]    Compiling raft-poc v0.1.0 (/opt/rustwide/workdir)
[INFO] [stdout] warning: field `last_applied` is never read
[INFO] [stdout]   --> src/raft/core.rs:81:9
[INFO] [stdout]    |
[INFO] [stdout] 77 | pub struct VolatileState {
[INFO] [stdout]    |            ------------- field in this struct
[INFO] [stdout] ...
[INFO] [stdout] 81 |     pub last_applied: u64,
[INFO] [stdout]    |         ^^^^^^^^^^^^
[INFO] [stdout]    |
[INFO] [stdout]    = note: `VolatileState` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout]    = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: fields `proposed_index` and `created_at` are never read
[INFO] [stdout]    --> src/raft/core.rs:104:9
[INFO] [stdout]     |
[INFO] [stdout] 102 | pub struct PendingProposal {
[INFO] [stdout]     |            --------------- fields in this struct
[INFO] [stdout] 103 |     /// The log index where this proposal would be placed if committed
[INFO] [stdout] 104 |     pub proposed_index: u64,
[INFO] [stdout]     |         ^^^^^^^^^^^^^^
[INFO] [stdout] ...
[INFO] [stdout] 112 |     pub created_at: Instant,
[INFO] [stdout]     |         ^^^^^^^^^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `PendingProposal` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: method `set_election_timeout` is never used
[INFO] [stdout]    --> src/raft/core.rs:231:12
[INFO] [stdout]     |
[INFO] [stdout] 195 | impl Node {
[INFO] [stdout]     | --------- method in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 231 |     pub fn set_election_timeout(&mut self, timeout_ms: u64) {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: method `get_pending_proposals` is never used
[INFO] [stdout]    --> src/raft/algorithm.rs:348:12
[INFO] [stdout]     |
[INFO] [stdout]  18 | impl Node {
[INFO] [stdout]     | --------- method in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 348 |     pub fn get_pending_proposals(&self) -> Vec<(u64, &crate::raft::core::PendingProposal)> {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: field `to` is never read
[INFO] [stdout]    --> src/raft/rpc.rs:134:9
[INFO] [stdout]     |
[INFO] [stdout] 130 |     AppendEntriesResponse {
[INFO] [stdout]     |     --------------------- field in this variant
[INFO] [stdout] ...
[INFO] [stdout] 134 |         to: NodeId,
[INFO] [stdout]     |         ^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `RpcMessage` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: field `to` is never read
[INFO] [stdout]    --> src/raft/rpc.rs:152:9
[INFO] [stdout]     |
[INFO] [stdout] 148 |     RequestVoteResponse {
[INFO] [stdout]     |     ------------------- field in this variant
[INFO] [stdout] ...
[INFO] [stdout] 152 |         to: NodeId,
[INFO] [stdout]     |         ^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `RpcMessage` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: field `from` is never read
[INFO] [stdout]    --> src/raft/rpc.rs:159:9
[INFO] [stdout]     |
[INFO] [stdout] 157 |     ClientCommand {
[INFO] [stdout]     |     ------------- field in this variant
[INFO] [stdout] 158 |         /// ID of the client (or simulation controller)
[INFO] [stdout] 159 |         from: NodeId,
[INFO] [stdout]     |         ^^^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `RpcMessage` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: methods `from`, `to`, and `message_type` are never used
[INFO] [stdout]    --> src/raft/rpc.rs:198:12
[INFO] [stdout]     |
[INFO] [stdout] 167 | impl RpcMessage {
[INFO] [stdout]     | --------------- methods in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 198 |     pub fn from(&self) -> NodeId {
[INFO] [stdout]     |            ^^^^
[INFO] [stdout] ...
[INFO] [stdout] 209 |     pub fn to(&self) -> NodeId {
[INFO] [stdout]     |            ^^
[INFO] [stdout] ...
[INFO] [stdout] 220 |     pub fn message_type(&self) -> &'static str {
[INFO] [stdout]     |            ^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `NodeHandle` is never constructed
[INFO] [stdout]   --> src/raft/simulation.rs:14:12
[INFO] [stdout]    |
[INFO] [stdout] 14 | pub struct NodeHandle {
[INFO] [stdout]    |            ^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: associated items `new`, `send`, and `create_pair` are never used
[INFO] [stdout]   --> src/raft/simulation.rs:25:12
[INFO] [stdout]    |
[INFO] [stdout] 23 | impl NodeHandle {
[INFO] [stdout]    | --------------- associated items in this implementation
[INFO] [stdout] 24 |     /// Creates a new NodeHandle with unbounded channels
[INFO] [stdout] 25 |     pub fn new(node_id: NodeId) -> Self {
[INFO] [stdout]    |            ^^^
[INFO] [stdout] ...
[INFO] [stdout] 35 |     pub fn send(&self, message: RpcMessage) -> Result<(), mpsc::error::SendError<RpcMessage>> {
[INFO] [stdout]    |            ^^^^
[INFO] [stdout] ...
[INFO] [stdout] 40 |     pub fn create_pair(node_id1: NodeId, node_id2: NodeId) -> (Self, Self) {
[INFO] [stdout]    |            ^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: method `all_node_ids` is never used
[INFO] [stdout]    --> src/raft/simulation.rs:116:12
[INFO] [stdout]     |
[INFO] [stdout]  56 | impl ClusterChannels {
[INFO] [stdout]     | -------------------- method in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 116 |     pub fn all_node_ids(&self) -> Vec<NodeId> {
[INFO] [stdout]     |            ^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: methods `receiver_count` and `get_stats` are never used
[INFO] [stdout]    --> src/raft/events.rs:619:12
[INFO] [stdout]     |
[INFO] [stdout] 502 | impl EventBroadcaster {
[INFO] [stdout]     | --------------------- methods in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 619 |     pub fn receiver_count(&self) -> usize {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^
[INFO] [stdout] ...
[INFO] [stdout] 624 |     pub fn get_stats(&self) -> EventBroadcasterStats {
[INFO] [stdout]     |            ^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `EventBroadcasterStats` is never constructed
[INFO] [stdout]    --> src/raft/events.rs:641:12
[INFO] [stdout]     |
[INFO] [stdout] 641 | pub struct EventBroadcasterStats {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: function `spawn_websocket_server` is never used
[INFO] [stdout]    --> src/raft/websocket.rs:558:14
[INFO] [stdout]     |
[INFO] [stdout] 558 | pub async fn spawn_websocket_server(
[INFO] [stdout]     |              ^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 55.07s
[INFO] running `Command { std: "docker" "inspect" "b9072ed4b198867b4876b007475f60011b6b48e01b7cd2de438a3071add8b2b6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "b9072ed4b198867b4876b007475f60011b6b48e01b7cd2de438a3071add8b2b6", kill_on_drop: false }`
[INFO] [stdout] b9072ed4b198867b4876b007475f60011b6b48e01b7cd2de438a3071add8b2b6
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] a1732e75fca0e8853b6935587731fb26f0c7bdd7ea4d9a69f21fe2a6b85605b8
[INFO] running `Command { std: "docker" "start" "-a" "a1732e75fca0e8853b6935587731fb26f0c7bdd7ea4d9a69f21fe2a6b85605b8", kill_on_drop: false }`
[INFO] [stderr]    Compiling raft-poc v0.1.0 (/opt/rustwide/workdir)
[INFO] [stdout] warning: unused imports: `EventBroadcaster` and `RaftEventType`
[INFO] [stdout]    --> src/raft/websocket.rs:603:31
[INFO] [stdout]     |
[INFO] [stdout] 603 |     use crate::raft::events::{EventBroadcaster, RaftEventType};
[INFO] [stdout]     |                               ^^^^^^^^^^^^^^^^  ^^^^^^^^^^^^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `#[warn(unused_imports)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused imports: `LogEntry` and `NodeId`
[INFO] [stdout]    --> src/raft/tests.rs:214:30
[INFO] [stdout]     |
[INFO] [stdout] 214 |     use super::super::core::{LogEntry, NodeId};
[INFO] [stdout]     |                              ^^^^^^^^  ^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `super::super::rpc::*`
[INFO] [stdout]    --> src/raft/tests.rs:376:9
[INFO] [stdout]     |
[INFO] [stdout] 376 |     use super::super::rpc::*;
[INFO] [stdout]     |         ^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `tokio::time::Duration`
[INFO] [stdout]    --> src/raft/tests.rs:378:9
[INFO] [stdout]     |
[INFO] [stdout] 378 |     use tokio::time::Duration;
[INFO] [stdout]     |         ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `super::super::events::EventBroadcaster`
[INFO] [stdout]  --> src/raft/integration_tests.rs:4:9
[INFO] [stdout]   |
[INFO] [stdout] 4 |     use super::super::events::EventBroadcaster;
[INFO] [stdout]   |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `std::collections::HashMap`
[INFO] [stdout]  --> src/raft/integration_tests.rs:7:9
[INFO] [stdout]   |
[INFO] [stdout] 7 |     use std::collections::HashMap;
[INFO] [stdout]   |         ^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `timeout`
[INFO] [stdout]  --> src/raft/integration_tests.rs:8:40
[INFO] [stdout]   |
[INFO] [stdout] 8 |     use tokio::time::{Duration, sleep, timeout};
[INFO] [stdout]   |                                        ^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused variable: `cluster_channels`
[INFO] [stdout]    --> src/raft/integration_tests.rs:324:14
[INFO] [stdout]     |
[INFO] [stdout] 324 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stdout]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stdout]     |
[INFO] [stdout]     = note: `#[warn(unused_variables)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused variable: `cluster_channels`
[INFO] [stdout]    --> src/raft/integration_tests.rs:353:14
[INFO] [stdout]     |
[INFO] [stdout] 353 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stdout]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused variable: `cluster_channels`
[INFO] [stdout]    --> src/raft/integration_tests.rs:574:14
[INFO] [stdout]     |
[INFO] [stdout] 574 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stdout]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: field `created_at` is never read
[INFO] [stdout]    --> src/raft/core.rs:112:9
[INFO] [stdout]     |
[INFO] [stdout] 102 | pub struct PendingProposal {
[INFO] [stdout]     |            --------------- field in this struct
[INFO] [stdout] ...
[INFO] [stdout] 112 |     pub created_at: Instant,
[INFO] [stdout]     |         ^^^^^^^^^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `PendingProposal` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stdout]     = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: method `set_election_timeout` is never used
[INFO] [stdout]    --> src/raft/core.rs:231:12
[INFO] [stdout]     |
[INFO] [stdout] 195 | impl Node {
[INFO] [stdout]     | --------- method in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 231 |     pub fn set_election_timeout(&mut self, timeout_ms: u64) {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: method `get_pending_proposals` is never used
[INFO] [stdout]    --> src/raft/algorithm.rs:348:12
[INFO] [stdout]     |
[INFO] [stdout]  18 | impl Node {
[INFO] [stdout]     | --------- method in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 348 |     pub fn get_pending_proposals(&self) -> Vec<(u64, &crate::raft::core::PendingProposal)> {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `NodeHandle` is never constructed
[INFO] [stdout]   --> src/raft/simulation.rs:14:12
[INFO] [stdout]    |
[INFO] [stdout] 14 | pub struct NodeHandle {
[INFO] [stdout]    |            ^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: associated items `new`, `send`, and `create_pair` are never used
[INFO] [stdout]   --> src/raft/simulation.rs:25:12
[INFO] [stdout]    |
[INFO] [stdout] 23 | impl NodeHandle {
[INFO] [stdout]    | --------------- associated items in this implementation
[INFO] [stdout] 24 |     /// Creates a new NodeHandle with unbounded channels
[INFO] [stdout] 25 |     pub fn new(node_id: NodeId) -> Self {
[INFO] [stdout]    |            ^^^
[INFO] [stdout] ...
[INFO] [stdout] 35 |     pub fn send(&self, message: RpcMessage) -> Result<(), mpsc::error::SendError<RpcMessage>> {
[INFO] [stdout]    |            ^^^^
[INFO] [stdout] ...
[INFO] [stdout] 40 |     pub fn create_pair(node_id1: NodeId, node_id2: NodeId) -> (Self, Self) {
[INFO] [stdout]    |            ^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: methods `receiver_count` and `get_stats` are never used
[INFO] [stdout]    --> src/raft/events.rs:619:12
[INFO] [stdout]     |
[INFO] [stdout] 502 | impl EventBroadcaster {
[INFO] [stdout]     | --------------------- methods in this implementation
[INFO] [stdout] ...
[INFO] [stdout] 619 |     pub fn receiver_count(&self) -> usize {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^
[INFO] [stdout] ...
[INFO] [stdout] 624 |     pub fn get_stats(&self) -> EventBroadcasterStats {
[INFO] [stdout]     |            ^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `EventBroadcasterStats` is never constructed
[INFO] [stdout]    --> src/raft/events.rs:641:12
[INFO] [stdout]     |
[INFO] [stdout] 641 | pub struct EventBroadcasterStats {
[INFO] [stdout]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: function `spawn_websocket_server` is never used
[INFO] [stdout]    --> src/raft/websocket.rs:558:14
[INFO] [stdout]     |
[INFO] [stdout] 558 | pub async fn spawn_websocket_server(
[INFO] [stdout]     |              ^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: function `wait_for_leader_election` is never used
[INFO] [stdout]   --> src/raft/integration_tests.rs:12:14
[INFO] [stdout]    |
[INFO] [stdout] 12 |     async fn wait_for_leader_election(
[INFO] [stdout]    |              ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 14.74s
[INFO] running `Command { std: "docker" "inspect" "a1732e75fca0e8853b6935587731fb26f0c7bdd7ea4d9a69f21fe2a6b85605b8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a1732e75fca0e8853b6935587731fb26f0c7bdd7ea4d9a69f21fe2a6b85605b8", kill_on_drop: false }`
[INFO] [stdout] a1732e75fca0e8853b6935587731fb26f0c7bdd7ea4d9a69f21fe2a6b85605b8
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+c90bcb9571b7aab0d8beaa2ce8a998ffaf079d38" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] c626eabf3fc97bc6756fa76856ed8fd96a2243f7fd985ecb0b3884f146189331
[INFO] running `Command { std: "docker" "start" "-a" "c626eabf3fc97bc6756fa76856ed8fd96a2243f7fd985ecb0b3884f146189331", kill_on_drop: false }`
[INFO] [stderr] warning: unused imports: `EventBroadcaster` and `RaftEventType`
[INFO] [stderr]    --> src/raft/websocket.rs:603:31
[INFO] [stderr]     |
[INFO] [stderr] 603 |     use crate::raft::events::{EventBroadcaster, RaftEventType};
[INFO] [stderr]     |                               ^^^^^^^^^^^^^^^^  ^^^^^^^^^^^^^
[INFO] [stderr]     |
[INFO] [stderr]     = note: `#[warn(unused_imports)]` (part of `#[warn(unused)]`) on by default
[INFO] [stderr] 
[INFO] [stderr] warning: unused imports: `LogEntry` and `NodeId`
[INFO] [stderr]    --> src/raft/tests.rs:214:30
[INFO] [stderr]     |
[INFO] [stderr] 214 |     use super::super::core::{LogEntry, NodeId};
[INFO] [stderr]     |                              ^^^^^^^^  ^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `super::super::rpc::*`
[INFO] [stderr]    --> src/raft/tests.rs:376:9
[INFO] [stderr]     |
[INFO] [stderr] 376 |     use super::super::rpc::*;
[INFO] [stderr]     |         ^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `tokio::time::Duration`
[INFO] [stderr]    --> src/raft/tests.rs:378:9
[INFO] [stderr]     |
[INFO] [stderr] 378 |     use tokio::time::Duration;
[INFO] [stderr]     |         ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `super::super::events::EventBroadcaster`
[INFO] [stderr]  --> src/raft/integration_tests.rs:4:9
[INFO] [stderr]   |
[INFO] [stderr] 4 |     use super::super::events::EventBroadcaster;
[INFO] [stderr]   |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `std::collections::HashMap`
[INFO] [stderr]  --> src/raft/integration_tests.rs:7:9
[INFO] [stderr]   |
[INFO] [stderr] 7 |     use std::collections::HashMap;
[INFO] [stderr]   |         ^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `timeout`
[INFO] [stderr]  --> src/raft/integration_tests.rs:8:40
[INFO] [stderr]   |
[INFO] [stderr] 8 |     use tokio::time::{Duration, sleep, timeout};
[INFO] [stderr]   |                                        ^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused variable: `cluster_channels`
[INFO] [stderr]    --> src/raft/integration_tests.rs:324:14
[INFO] [stderr]     |
[INFO] [stderr] 324 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stderr]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stderr]     |
[INFO] [stderr]     = note: `#[warn(unused_variables)]` (part of `#[warn(unused)]`) on by default
[INFO] [stderr] 
[INFO] [stderr] warning: unused variable: `cluster_channels`
[INFO] [stderr]    --> src/raft/integration_tests.rs:353:14
[INFO] [stderr]     |
[INFO] [stderr] 353 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stderr]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stderr] 
[INFO] [stderr] warning: unused variable: `cluster_channels`
[INFO] [stderr]    --> src/raft/integration_tests.rs:574:14
[INFO] [stderr]     |
[INFO] [stderr] 574 |         let (cluster_channels, _event_broadcaster, join_handles) =
[INFO] [stderr]     |              ^^^^^^^^^^^^^^^^ help: if this is intentional, prefix it with an underscore: `_cluster_channels`
[INFO] [stderr] 
[INFO] [stderr] warning: field `created_at` is never read
[INFO] [stderr]    --> src/raft/core.rs:112:9
[INFO] [stderr]     |
[INFO] [stderr] 102 | pub struct PendingProposal {
[INFO] [stderr]     |            --------------- field in this struct
[INFO] [stderr] ...
[INFO] [stderr] 112 |     pub created_at: Instant,
[INFO] [stderr]     |         ^^^^^^^^^^
[INFO] [stderr]     |
[INFO] [stderr]     = note: `PendingProposal` has derived impls for the traits `Clone` and `Debug`, but these are intentionally ignored during dead code analysis
[INFO] [stderr]     = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stderr] 
[INFO] [stderr] warning: method `set_election_timeout` is never used
[INFO] [stderr]    --> src/raft/core.rs:231:12
[INFO] [stderr]     |
[INFO] [stderr] 195 | impl Node {
[INFO] [stderr]     | --------- method in this implementation
[INFO] [stderr] ...
[INFO] [stderr] 231 |     pub fn set_election_timeout(&mut self, timeout_ms: u64) {
[INFO] [stderr]     |            ^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: method `get_pending_proposals` is never used
[INFO] [stderr]    --> src/raft/algorithm.rs:348:12
[INFO] [stderr]     |
[INFO] [stderr]  18 | impl Node {
[INFO] [stderr]     | --------- method in this implementation
[INFO] [stderr] ...
[INFO] [stderr] 348 |     pub fn get_pending_proposals(&self) -> Vec<(u64, &crate::raft::core::PendingProposal)> {
[INFO] [stderr]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: struct `NodeHandle` is never constructed
[INFO] [stderr]   --> src/raft/simulation.rs:14:12
[INFO] [stderr]    |
[INFO] [stderr] 14 | pub struct NodeHandle {
[INFO] [stderr]    |            ^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: associated items `new`, `send`, and `create_pair` are never used
[INFO] [stderr]   --> src/raft/simulation.rs:25:12
[INFO] [stderr]    |
[INFO] [stderr] 23 | impl NodeHandle {
[INFO] [stderr]    | --------------- associated items in this implementation
[INFO] [stderr] 24 |     /// Creates a new NodeHandle with unbounded channels
[INFO] [stderr] 25 |     pub fn new(node_id: NodeId) -> Self {
[INFO] [stderr]    |            ^^^
[INFO] [stderr] ...
[INFO] [stderr] 35 |     pub fn send(&self, message: RpcMessage) -> Result<(), mpsc::error::SendError<RpcMessage>> {
[INFO] [stderr]    |            ^^^^
[INFO] [stderr] ...
[INFO] [stderr] 40 |     pub fn create_pair(node_id1: NodeId, node_id2: NodeId) -> (Self, Self) {
[INFO] [stderr]    |            ^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: methods `receiver_count` and `get_stats` are never used
[INFO] [stderr]    --> src/raft/events.rs:619:12
[INFO] [stderr]     |
[INFO] [stderr] 502 | impl EventBroadcaster {
[INFO] [stderr]     | --------------------- methods in this implementation
[INFO] [stderr] ...
[INFO] [stderr] 619 |     pub fn receiver_count(&self) -> usize {
[INFO] [stderr]     |            ^^^^^^^^^^^^^^
[INFO] [stderr] ...
[INFO] [stderr] 624 |     pub fn get_stats(&self) -> EventBroadcasterStats {
[INFO] [stderr]     |            ^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: struct `EventBroadcasterStats` is never constructed
[INFO] [stderr]    --> src/raft/events.rs:641:12
[INFO] [stderr]     |
[INFO] [stderr] 641 | pub struct EventBroadcasterStats {
[INFO] [stderr]     |            ^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: function `spawn_websocket_server` is never used
[INFO] [stderr]    --> src/raft/websocket.rs:558:14
[INFO] [stderr]     |
[INFO] [stderr] 558 | pub async fn spawn_websocket_server(
[INFO] [stderr]     |              ^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: function `wait_for_leader_election` is never used
[INFO] [stderr]   --> src/raft/integration_tests.rs:12:14
[INFO] [stderr]    |
[INFO] [stderr] 12 |     async fn wait_for_leader_election(
[INFO] [stderr]    |              ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: `raft-poc` (bin "raft-poc" test) generated 19 warnings (run `cargo fix --bin "raft-poc" -p raft-poc --tests` to apply 10 suggestions)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.26s
[INFO] [stderr]      Running unittests src/main.rs (/opt/rustwide/target/debug/deps/raft_poc-a295aac823063056)
[INFO] [stdout] 
[INFO] [stdout] running 48 tests
[INFO] [stdout] 2025-11-11T06:50:53.786426Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting concurrent proposals test
[INFO] [stdout] 2025-11-11T06:50:53.786896Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.787013Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting election timeout ranges test
[INFO] [stdout] 2025-11-11T06:50:53.787041Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] test raft::events::tests::test_event_creation ... ok
[INFO] [stdout] test raft::events::tests::test_event_broadcaster ... ok
[INFO] [stdout] test raft::events::tests::test_event_deduplication ... ok
[INFO] [stdout] 2025-11-11T06:50:53.787315Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader election test with 3 nodes
[INFO] [stdout] test raft::events::tests::test_event_deduplication_time_window ... ok
[INFO] [stdout] 2025-11-11T06:50:53.787346Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.786476Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting detailed election process test for visualization
[INFO] [stdout] test raft::events::tests::test_event_serialization ... ok
[INFO] [stdout] 2025-11-11T06:50:53.787367Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.787465Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.787515Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.787543Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.787544Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader election test with 5 nodes
[INFO] [stdout] 2025-11-11T06:50:53.787565Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:50:53.787567Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.787577Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:50:53.787622Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.787669Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.787701Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.787999Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.788031Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.788045Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.788056Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.788068Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned for timeout testing
[INFO] [stdout] 2025-11-11T06:50:53.788090Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.788121Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.788145Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.788152Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting heartbeat failure detection test
[INFO] [stdout] 2025-11-11T06:50:53.788170Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.788332Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting commit index advancement test
[INFO] [stdout] 2025-11-11T06:50:53.788367Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:50:53.788393Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.788431Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.788449Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.788458Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.788476Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for stable leadership
[INFO] [stdout] 2025-11-11T06:50:53.788498Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.788533Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.788562Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.788676Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.788724Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.788738Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.788760Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.788771Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:50:53.788793Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.788833Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.788884Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.788940Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.788977Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.789003Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:50:53.789416Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting split vote resolution test
[INFO] [stdout] 2025-11-11T06:50:53.789438Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 4 nodes
[INFO] [stdout] 2025-11-11T06:50:53.789605Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.789638Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.789680Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.789691Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.789711Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for natural election
[INFO] [stdout] 2025-11-11T06:50:53.789802Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.789844Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.789866Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.790182Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.790706Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.790840Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.790854Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.790944Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.790978Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.791008Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:50:53.791024Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.791081Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.791227Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.791258Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.791259Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader forwarding test
[INFO] [stdout] 2025-11-11T06:50:53.791292Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:50:53.791669Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting proposal rejection cases test
[INFO] [stdout] 2025-11-11T06:50:53.792740Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.791932Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.791628Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting split vote test with 4 nodes
[INFO] [stdout] 2025-11-11T06:50:53.792258Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting network partition recovery test
[INFO] [stdout] 2025-11-11T06:50:53.791111Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.791049Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.793373Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.793461Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.793492Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.793512Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.793388Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.793534Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:50:53.793542Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.793555Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.793564Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:50:53.791269Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.793575Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.793603Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.793618Z  INFO raft_poc::raft::simulation: ✅ All 4 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.793631Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 4-node cluster spawned
[INFO] [stdout] 2025-11-11T06:50:53.793651Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.793678Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.793699Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.793729Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.793808Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.793818Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:50:53.793838Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.793850Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.793983Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:50:53.794159Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.794252Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.794292Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.794305Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.794315Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.794324Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:50:53.794339Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.794351Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node cluster spawned, establishing stable leadership
[INFO] [stdout] 2025-11-11T06:50:53.794382Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.794412Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.794439Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.794458Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.794495Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:50:53.794240Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.794587Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.794620Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.794653Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:50:53.793278Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 4 nodes
[INFO] [stdout] 2025-11-11T06:50:53.796399Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.797600Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.796655Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting log replication test
[INFO] [stdout] 2025-11-11T06:50:53.796491Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.798071Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.798170Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.798582Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:50:53.797752Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.798141Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.799007Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.799636Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.799726Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.799320Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:50:53.800432Z  INFO raft_poc::raft::simulation: ✅ All 4 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.800851Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.799575Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.801299Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.807993Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.808131Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.801872Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.808380Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.809449Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.793270Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting heartbeat maintenance test
[INFO] [stdout] 2025-11-11T06:50:53.809705Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.810114Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.810625Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting proposal consensus flow test for visualization
[INFO] [stdout] 2025-11-11T06:50:53.809799Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.809600Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:50:53.811539Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.811564Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.811874Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.811917Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.811937Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.811948Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.811962Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:50:53.811989Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.812021Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.812055Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.811583Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.812123Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.812139Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.812154Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election and heartbeat establishment
[INFO] [stdout] 2025-11-11T06:50:53.812176Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.812207Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.812233Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:53.812291Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting normal cluster operation test
[INFO] [stdout] 2025-11-11T06:50:53.812310Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:53.812532Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:53.812561Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:53.812574Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:53.812585Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:50:53.812607Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:50:53.812640Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:53.812664Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:50:55.798016Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Election period completed, checking for leader
[INFO] [stdout] 2025-11-11T06:50:55.798070Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Leader election test completed
[INFO] [stdout] 2025-11-11T06:50:55.798163Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] test raft::integration_tests::integration_tests::test_leader_election_3_nodes ... ok
[INFO] [stdout] 2025-11-11T06:50:55.798670Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.798719Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] test raft::tests::algorithm_tests::test_become_candidate ... ok
[INFO] [stdout] 2025-11-11T06:50:55.799022Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.799058Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] test raft::tests::algorithm_tests::test_become_leader ... ok
[INFO] [stdout] 2025-11-11T06:50:55.799436Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.799474Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.799495Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'cmd1' → pending proposal at index 1 (term 0) | Need 2/3 acks for consensus node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.799515Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.799533Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'cmd1' committed to log at index 1 (term 0) | Acknowledged by: [1] node_id=1
[INFO] [stdout] test raft::tests::algorithm_tests::test_client_submit ... ok
[INFO] [stdout] 2025-11-11T06:50:55.799787Z  INFO raft_poc::raft::algorithm: Updating term from 0 to 1 due to AppendEntries from leader 0 node_id=1
[INFO] [stdout] test raft::tests::algorithm_tests::test_handle_append_entries_basic ... ok
[INFO] [stdout] test raft::tests::algorithm_tests::test_handle_request_vote_basic ... ok
[INFO] [stdout] test raft::tests::core_tests::test_client_submit_as_follower ... ok
[INFO] [stdout] 2025-11-11T06:50:55.801265Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'test command' → pending proposal at index 1 (term 0) | Need 2/3 acks for consensus node_id=0
[INFO] [stdout] test raft::tests::core_tests::test_client_submit_as_leader ... ok
[INFO] [stdout] 2025-11-11T06:50:55.801672Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'test command' → pending proposal at index 1 (term 1) | Need 2/3 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:50:55.801705Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=0
[INFO] [stdout] 2025-11-11T06:50:55.801716Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'test command' committed to log at index 1 (term 1) | Acknowledged by: [0] node_id=0
[INFO] [stdout] test raft::tests::core_tests::test_commit_proposal ... ok
[INFO] [stdout] test raft::tests::core_tests::test_election_timeout ... ok
[INFO] [stdout] 2025-11-11T06:50:55.809239Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:55.809287Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=0
[INFO] [stdout] test raft::tests::core_tests::test_heartbeat_timing ... ok
[INFO] [stdout] test raft::tests::core_tests::test_last_log_index_and_term ... ok
[INFO] [stdout] 2025-11-11T06:50:55.810235Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command1' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:55.810305Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command2' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:55.810363Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command3' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] test raft::tests::core_tests::test_leader_volatile_state_initialization ... ok
[INFO] [stdout] test raft::tests::core_tests::test_log_entry_creation ... ok
[INFO] [stdout] test raft::tests::core_tests::test_log_term_retrieval ... ok
[INFO] [stdout] test raft::tests::core_tests::test_node_creation ... ok
[INFO] [stdout] test raft::tests::core_tests::test_pending_proposal_acknowledgments ... ok
[INFO] [stdout] test raft::tests::core_tests::test_pending_proposal_creation ... ok
[INFO] [stdout] test raft::tests::core_tests::test_persistent_state_default ... ok
[INFO] [stdout] test raft::tests::core_tests::test_volatile_state_default ... ok
[INFO] [stdout] test raft::tests::rpc_tests::test_append_entries_request_creation ... ok
[INFO] [stdout] test raft::tests::rpc_tests::test_request_vote_request_creation ... ok
[INFO] [stdout] test raft::tests::rpc_tests::test_rpc_message_append_entries_request ... ok
[INFO] [stdout] test raft::tests::rpc_tests::test_rpc_message_client_command ... ok
[INFO] [stdout] test raft::tests::simulation_tests::test_cluster_channels_creation ... ok
[INFO] [stdout] 2025-11-11T06:50:55.879221Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:50:55.879527Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:50:55.879605Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:50:55.879660Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:50:55.879711Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] test raft::tests::simulation_tests::test_spawn_cluster ... ok
[INFO] [stdout] test raft::websocket::tests::test_event_serialization ... ok
[INFO] [stdout] test raft::websocket::tests::test_websocket_config ... ok
[INFO] [stdout] 2025-11-11T06:50:55.899662Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_1' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.001172Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_2' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.102698Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_3' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.212395Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_4' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.303058Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.303140Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.303212Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.303275Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.303317Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.332161Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.332303Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.332351Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.332411Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 0 requesting votes from 3 nodes for term 1 (need 3/4 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.332458Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 3 nodes for election term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.347315Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.347396Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.347421Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.347444Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.347484Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.349122Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.349194Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.349229Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.349263Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 1 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.349303Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.350035Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.350116Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.350150Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.350186Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.350229Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.369037Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.369122Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.369147Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.369187Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.369229Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.400175Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.400249Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.400271Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.400290Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.400322Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.413038Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.413180Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.413230Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.413283Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.413359Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:56.462156Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=4
[INFO] [stdout] 2025-11-11T06:50:56.462241Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:56.462268Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=4
[INFO] [stdout] 2025-11-11T06:50:56.462313Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 4 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=4
[INFO] [stdout] 2025-11-11T06:50:56.462359Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:56.485140Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.485283Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.485313Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.485337Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 0 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.485396Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.789110Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Submitting multiple concurrent proposals
[INFO] [stdout] 2025-11-11T06:50:56.789110Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Simulating leader failure to test heartbeat failure detection
[INFO] [stdout] 2025-11-11T06:50:56.789367Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_LEADER_FAILURE' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.789394Z  INFO raft_poc::raft::simulation: 👑 Received leader failure simulation command, state: Follower node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.795005Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 First election completed, triggering manual election
[INFO] [stdout] 2025-11-11T06:50:56.795042Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Election period completed for 5-node cluster
[INFO] [stdout] 2025-11-11T06:50:56.795079Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node leader election test completed
[INFO] [stdout] 2025-11-11T06:50:56.795525Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing systematic forwarding from each node
[INFO] [stdout] 2025-11-11T06:50:56.795568Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_0' to node 0
[INFO] [stdout] 2025-11-11T06:50:56.795652Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.796177Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing cluster behavior under stress (simulating partition scenarios)
[INFO] [stdout] test raft::integration_tests::integration_tests::test_leader_election_5_nodes ... ok
[INFO] [stdout] 2025-11-11T06:50:56.800895Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing proposal submission to follower (should forward)
[INFO] [stdout] 2025-11-11T06:50:56.813154Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Submitting test proposal for consensus flow visualization
[INFO] [stdout] 2025-11-11T06:50:56.813295Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'TEST_PROPOSAL_FOR_VISUALIZATION' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:56.813969Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Observing heartbeat patterns
[INFO] [stdout] 2025-11-11T06:50:56.846152Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.846229Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.846253Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.846277Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 1 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.846312Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:56.892414Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_2' by Candidate 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.000217Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.000281Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.000301Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.000323Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 0 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.000347Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.026928Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.026996Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.027023Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.027053Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 2 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.027082Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.102575Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_1' by Candidate 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.185830Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.185929Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.185955Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.185977Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 0 requesting votes from 3 nodes for term 1 (need 3/4 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.186013Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 3 nodes for election term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.196822Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_1' to node 1
[INFO] [stdout] 2025-11-11T06:50:57.202878Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.202971Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.203008Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.203048Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 0 requesting votes from 2 nodes for term 1 (need 2/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.203088Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 2 nodes for election term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.304862Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.304972Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_1' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.305026Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_4' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.305084Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.305111Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.305136Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_3' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.305243Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/2 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.305291Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.305329Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.305389Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.305444Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.336058Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 0 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.336146Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 0 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.336170Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 3 granted vote to candidate 0 for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:50:57.336196Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.336221Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 3/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.336230Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.336240Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 3 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.336258Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.336276Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.349194Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.349280Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.349306Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 3 granted vote to candidate 2 for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:50:57.349328Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 4 granted vote to candidate 2 for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.349370Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/3 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.349393Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 3/3 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.349402Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.349413Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.349435Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.349453Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.352379Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 1 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.352456Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 1 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.352500Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.352555Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/2 votes for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.352580Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.352594Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.352614Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 1 transitioning Candidate → Leader (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.352642Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.371839Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.371945Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_ELECTION_TIMEOUT' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.371993Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.372039Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/2 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.372058Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.372071Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.372080Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.372099Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.402157Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.402260Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.402298Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 2/2 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.402322Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.402335Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.402358Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.402381Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.404008Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_2' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.404052Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'FORWARDING_TEST_2' from follower 2 to leader 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.404102Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_2' by Leader 1 (WILL PROCESS) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404130Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'FORWARDING_TEST_2' → pending proposal at index 1 (term 1) | Need 2/3 acks for consensus node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404144Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'FORWARDING_TEST_2' accepted as pending proposal at index 1 (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404172Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404182Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 1 to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404194Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404215Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 1 → follower 0 (1 entries) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404245Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404254Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404278Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 1 → follower 2 (1 entries) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404289Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404317Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.404350Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.404399Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.404427Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.404473Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 0 acknowledged proposal 1 → 2/2 acks (CONSENSUS ACHIEVED!) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404504Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404517Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.404527Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'FORWARDING_TEST_2' committed to log at index 1 (term 1) | Acknowledged by: [1, 0] node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.414182Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.414273Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.414313Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/2 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.414326Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.414338Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.414347Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.414367Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.463986Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 4 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.464080Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_PARTITION' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.464133Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 4 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.464166Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 3 granted vote to candidate 4 for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:50:57.464195Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 4 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.464215Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_PARTITION' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.464265Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/3 votes for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.464282Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 3/3 votes for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.464291Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.464301Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.464310Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 4 transitioning Candidate → Leader (term 1) node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.464330Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 4 node_id=4
[INFO] [stdout] 2025-11-11T06:50:57.486961Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 0 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.487058Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 0 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.487097Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/2 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.487110Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.487122Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.487131Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.487151Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.598166Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_2' to node 2
[INFO] [stdout] 2025-11-11T06:50:57.705137Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Proposal rejection testing completed
[INFO] [stdout] 2025-11-11T06:50:57.802109Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Split vote scenario test period completed
[INFO] [stdout] 2025-11-11T06:50:57.802160Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Split vote scenario test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_split_vote_scenario ... ok
[INFO] [stdout] 2025-11-11T06:50:57.811043Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Log replication test completed
[INFO] [stdout] 2025-11-11T06:50:57.811085Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Log replication test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_log_replication ... ok
[INFO] [stdout] 2025-11-11T06:50:57.847164Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 1 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:57.847346Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 1 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:57.847459Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/2 votes for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.847560Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.847597Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.847657Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 1 transitioning Candidate → Leader (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.847700Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:57.999247Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_3' to node 3
[INFO] [stdout] 2025-11-11T06:50:58.001469Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 0 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.001555Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_2' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.001605Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 0 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.001638Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_1' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.001674Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 3 granted vote to candidate 0 for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:50:58.001726Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_3' by Follower 3 (WILL REJECT) node_id=3
[INFO] [stdout] 2025-11-11T06:50:58.001827Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 4 granted vote to candidate 0 for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:50:58.001960Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.002036Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 3/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.002082Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.002118Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.002145Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.002181Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.028373Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 2 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.028481Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 2 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.028524Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/2 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.028548Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.028561Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.028585Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.028605Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.186538Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 3 granted vote to candidate 0 for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:50:58.186642Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 0 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.186673Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 0 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.186711Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 3! Now have 2/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.186739Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 3/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.186749Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.186766Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 3 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.186775Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.186801Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.204477Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 0 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.204566Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 0 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.204602Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 2! Now have 2/2 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.204621Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.204633Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.204649Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.204669Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406046Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_4' to node 4
[INFO] [stdout] 2025-11-11T06:50:58.406123Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_4' by Follower 4 (WILL REJECT) node_id=4
[INFO] [stdout] 2025-11-11T06:50:58.406141Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'FORWARDING_FROM_NODE_4' from follower 4 to leader 0 node_id=4
[INFO] [stdout] 2025-11-11T06:50:58.406173Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_4' by Leader 0 (WILL PROCESS) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406192Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'FORWARDING_FROM_NODE_4' → pending proposal at index 1 (term 1) | Need 3/5 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406202Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'FORWARDING_FROM_NODE_4' accepted as pending proposal at index 1 (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406218Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406227Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 1 to 4 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406238Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406258Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 1 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406270Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406277Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406287Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 2 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406296Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406303Z  INFO raft_poc::raft::simulation: 📤 → Follower 3: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406312Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 3 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406320Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 3 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406327Z  INFO raft_poc::raft::simulation: 📤 → Follower 4: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406336Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 4 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406344Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 4 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406363Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.406379Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.406403Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.406412Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.406431Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=3
[INFO] [stdout] 2025-11-11T06:50:58.406440Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=3
[INFO] [stdout] 2025-11-11T06:50:58.406459Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=4
[INFO] [stdout] 2025-11-11T06:50:58.406470Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=4
[INFO] [stdout] 2025-11-11T06:50:58.406501Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 1 acknowledged proposal 1 → 2/3 acks (waiting for more...) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.406996Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.407021Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 0 → leader 1 for proposal 1 (2/2 acks, consensus: true) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.407033Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 1 → 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.407050Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.795141Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Split vote resolution test period completed
[INFO] [stdout] 2025-11-11T06:50:58.795190Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Split vote scenario test completed
[INFO] [stdout] 2025-11-11T06:50:58.796090Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Manual election completed
[INFO] [stdout] 2025-11-11T06:50:58.796106Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Detailed election process test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_split_vote_resolution ... ok
[INFO] [stdout] test raft::integration_tests::integration_tests::test_election_process_detailed ... ok
[INFO] [stdout] 2025-11-11T06:50:58.813844Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.813919Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'normal_op_0' from follower 0 to leader 2 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.813970Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_0' by Leader 2 (WILL PROCESS) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814004Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'normal_op_0' → pending proposal at index 1 (term 1) | Need 2/3 acks for consensus node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814028Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_0' accepted as pending proposal at index 1 (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814046Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814064Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 1 to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814076Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814099Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 2 → follower 0 (1 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814160Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814487Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814571Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 2 → follower 1 (1 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814617Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.814771Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.814862Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.815015Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.815097Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.815295Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 0 acknowledged proposal 1 → 2/2 acks (CONSENSUS ACHIEVED!) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.815378Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.815435Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.815500Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'normal_op_0' committed to log at index 1 (term 1) | Acknowledged by: [2, 0] node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.816973Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 First proposal completed, submitting to different node
[INFO] [stdout] 2025-11-11T06:50:58.817042Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'TEST_FORWARDING_PROPOSAL' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.817064Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'TEST_FORWARDING_PROPOSAL' from follower 1 to leader 0 node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.817094Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'TEST_FORWARDING_PROPOSAL' by Leader 0 (WILL PROCESS) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817117Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'TEST_FORWARDING_PROPOSAL' → pending proposal at index 1 (term 1) | Need 2/3 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817127Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'TEST_FORWARDING_PROPOSAL' accepted as pending proposal at index 1 (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817140Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817155Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 1 to 2 followers node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817165Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817193Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 1 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817205Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817213Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817233Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 0 → follower 2 (1 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817243Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817270Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.817292Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:50:58.817329Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.817347Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:50:58.817377Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 1 acknowledged proposal 1 → 2/2 acks (CONSENSUS ACHIEVED!) node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817397Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817406Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=0
[INFO] [stdout] 2025-11-11T06:50:58.817414Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'TEST_FORWARDING_PROPOSAL' committed to log at index 1 (term 1) | Acknowledged by: [0, 1] node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.015235Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_1' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.015287Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'normal_op_1' from follower 1 to leader 2 node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.316130Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Commit index advancement test completed
[INFO] [stdout] 2025-11-11T06:50:59.316174Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Commit index advancement test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_commit_index_advancement ... ok
[INFO] [stdout] 2025-11-11T06:50:59.407980Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.408036Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 1 → leader 0 for proposal 1 (2/3 acks, consensus: false) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.408072Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 2 acknowledged proposal 1 → 3/3 acks (CONSENSUS ACHIEVED!) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.408088Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 3/3 acks - ready to commit! node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.408099Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 1 achieved consensus → moving to committed log node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.408107Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'FORWARDING_FROM_NODE_4' committed to log at index 1 (term 1) | Acknowledged by: [0, 1, 2] node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.714041Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Proposal rejection cases test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_proposal_rejection_cases ... ok
[INFO] [stdout] 2025-11-11T06:50:59.790028Z  INFO raft_poc::raft::integration_tests::integration_tests: ⏱️ Election occurred within 6 seconds
[INFO] [stdout] 2025-11-11T06:50:59.790073Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Election timeout ranges test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_election_timeout_ranges ... ok
[INFO] [stdout] 2025-11-11T06:50:59.816774Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816834Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 0 → leader 2 for proposal 1 (2/2 acks, consensus: true) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816850Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 1 → 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816871Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816939Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_1' by Leader 2 (WILL PROCESS) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816972Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'normal_op_1' → pending proposal at index 2 (term 1) | Need 2/3 acks for consensus node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.816995Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_1' accepted as pending proposal at index 2 (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817013Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817023Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817040Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817062Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 2 → follower 0 (2 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817084Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817101Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817116Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 2 → follower 1 (1 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817134Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817157Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_2' by Leader 2 (WILL PROCESS) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817170Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'normal_op_2' → pending proposal at index 2 (term 1) | Need 2/3 acks for consensus node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817183Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_2' accepted as pending proposal at index 2 (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817198Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817207Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817217Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817247Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 2 → follower 0 (2 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817260Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817269Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817282Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 1 LogEntryProposed events from leader 2 → follower 1 (1 entries) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817292Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817335Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 2 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.817356Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.817384Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 2 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.817397Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.817427Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.817440Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.817470Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.817483Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:50:59.817522Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 0 acknowledged proposal 2 → 2/2 acks (CONSENSUS ACHIEVED!) node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817537Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 2 has 2/2 acks - ready to commit! node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817547Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 2 achieved consensus → moving to committed log node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.817557Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'normal_op_2' committed to log at index 2 (term 1) | Acknowledged by: [2, 0] node_id=2
[INFO] [stdout] 2025-11-11T06:50:59.819121Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 1 node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.819155Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 1 → leader 0 for proposal 1 (2/2 acks, consensus: true) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.819168Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 1 → 1) node_id=0
[INFO] [stdout] 2025-11-11T06:50:59.819186Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=0
[INFO] [stdout] 2025-11-11T06:51:00.410182Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 2 node_id=0
[INFO] [stdout] 2025-11-11T06:51:00.410235Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 2 → leader 0 for proposal 1 (3/3 acks, consensus: true) node_id=0
[INFO] [stdout] 2025-11-11T06:51:00.410248Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 1 → 1) node_id=0
[INFO] [stdout] 2025-11-11T06:51:00.410268Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=0
[INFO] [stdout] 2025-11-11T06:51:00.818171Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Proposal consensus flow test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_proposal_consensus_flow ... ok
[INFO] [stdout] 2025-11-11T06:51:00.819191Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=2
[INFO] [stdout] 2025-11-11T06:51:00.819245Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 0 → leader 2 for proposal 2 (2/2 acks, consensus: true) node_id=2
[INFO] [stdout] 2025-11-11T06:51:00.819259Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 2 → 2) node_id=2
[INFO] [stdout] 2025-11-11T06:51:00.819280Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=2
[INFO] [stdout] 2025-11-11T06:51:01.047554Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Concurrent proposals test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_concurrent_proposals ... ok
[INFO] [stdout] 2025-11-11T06:51:01.200556Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Partition simulation completed, observing recovery
[INFO] [stdout] 2025-11-11T06:51:01.419540Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Normal operation test completed
[INFO] [stdout] 2025-11-11T06:51:01.419588Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Normal cluster operation test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_normal_cluster_operation ... ok
[INFO] [stdout] 2025-11-11T06:51:01.809841Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Leader forwarding test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_leader_forwarding ... ok
[INFO] [stdout] 2025-11-11T06:51:01.814548Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Heartbeat maintenance test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_heartbeat_maintenance ... ok
[INFO] [stdout] 2025-11-11T06:51:02.790166Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Heartbeat failure detection test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_heartbeat_failure_detection ... ok
[INFO] [stdout] 2025-11-11T06:51:04.202169Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Network partition recovery test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_network_partition_recovery ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 48 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 10.42s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "c626eabf3fc97bc6756fa76856ed8fd96a2243f7fd985ecb0b3884f146189331", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "c626eabf3fc97bc6756fa76856ed8fd96a2243f7fd985ecb0b3884f146189331", kill_on_drop: false }`
[INFO] [stdout] c626eabf3fc97bc6756fa76856ed8fd96a2243f7fd985ecb0b3884f146189331