[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 try#c2e32f1c9652b13ed99608599c1e855462f421f3 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-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc2/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-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/tomas-rampas/raft-consensus-poc on toolchain c2e32f1c9652b13ed99608599c1e855462f421f3
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "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" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/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" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 609b7a0a60dde7c093602854082db4cf23aa478cd88e2cebd6095dec2d32662e
[INFO] running `Command { std: "docker" "start" "-a" "609b7a0a60dde7c093602854082db4cf23aa478cd88e2cebd6095dec2d32662e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "609b7a0a60dde7c093602854082db4cf23aa478cd88e2cebd6095dec2d32662e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "609b7a0a60dde7c093602854082db4cf23aa478cd88e2cebd6095dec2d32662e", kill_on_drop: false }`
[INFO] [stdout] 609b7a0a60dde7c093602854082db4cf23aa478cd88e2cebd6095dec2d32662e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/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" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 949319aa3586962e98682e323097b75437d0dea133b2f73f605b94cb008268c8
[INFO] running `Command { std: "docker" "start" "-a" "949319aa3586962e98682e323097b75437d0dea133b2f73f605b94cb008268c8", kill_on_drop: false }`
[INFO] [stderr]    Compiling version_check v0.9.5
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling typenum v1.18.0
[INFO] [stderr]    Compiling http v0.2.12
[INFO] [stderr]    Compiling cpufeatures v0.2.17
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling signal-hook-registry v1.4.6
[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 tracing-core v0.1.34
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling utf-8 v0.7.6
[INFO] [stderr]    Compiling data-encoding v2.9.0
[INFO] [stderr]    Compiling zerovec v0.11.3
[INFO] [stderr]    Compiling byteorder v1.5.0
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling generic-array v0.14.7
[INFO] [stderr]    Compiling multer v2.1.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.11
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling regex-syntax v0.6.29
[INFO] [stderr]    Compiling regex-syntax v0.8.5
[INFO] [stderr]    Compiling memchr v2.7.5
[INFO] [stderr]    Compiling serde_json v1.0.142
[INFO] [stderr]    Compiling parking_lot v0.12.4
[INFO] [stderr]    Compiling pin-project-internal v1.1.10
[INFO] [stderr]    Compiling socket2 v0.5.10
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling tokio v1.47.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling base64 v0.21.7
[INFO] [stderr]    Compiling spin v0.9.8
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling tinystr v0.8.1
[INFO] [stderr]    Compiling potential_utf v0.1.2
[INFO] [stderr]    Compiling http-body v0.4.6
[INFO] [stderr]    Compiling headers-core v0.2.0
[INFO] [stderr]    Compiling icu_locale_core v2.0.0
[INFO] [stderr]    Compiling icu_collections v2.0.0
[INFO] [stderr]    Compiling block-buffer v0.10.4
[INFO] [stderr]    Compiling crypto-common v0.1.6
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling digest v0.10.7
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling scoped-tls v1.0.1
[INFO] [stderr]    Compiling icu_provider v2.0.0
[INFO] [stderr]    Compiling pin-project v1.1.10
[INFO] [stderr]    Compiling sha1 v0.10.6
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling icu_properties v2.0.1
[INFO] [stderr]    Compiling icu_normalizer v2.0.0
[INFO] [stderr]    Compiling headers v0.3.9
[INFO] [stderr]    Compiling regex-automata v0.1.10
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling chrono v0.4.41
[INFO] [stderr]    Compiling matchers v0.1.0
[INFO] [stderr]    Compiling idna_adapter v1.2.1
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling regex v1.11.1
[INFO] [stderr]    Compiling tungstenite v0.21.0
[INFO] [stderr]    Compiling tungstenite v0.20.1
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling tokio-util v0.7.16
[INFO] [stderr]    Compiling tokio-tungstenite v0.20.1
[INFO] [stderr]    Compiling h2 v0.3.27
[INFO] [stderr]    Compiling tokio-tungstenite v0.21.0
[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 51.26s
[INFO] running `Command { std: "docker" "inspect" "949319aa3586962e98682e323097b75437d0dea133b2f73f605b94cb008268c8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "949319aa3586962e98682e323097b75437d0dea133b2f73f605b94cb008268c8", kill_on_drop: false }`
[INFO] [stdout] 949319aa3586962e98682e323097b75437d0dea133b2f73f605b94cb008268c8
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/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" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 8ee7496ab689b362095277abe3bd83005a7301dc323f6ae8725abadef5f7c436
[INFO] running `Command { std: "docker" "start" "-a" "8ee7496ab689b362095277abe3bd83005a7301dc323f6ae8725abadef5f7c436", 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 13.67s
[INFO] running `Command { std: "docker" "inspect" "8ee7496ab689b362095277abe3bd83005a7301dc323f6ae8725abadef5f7c436", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "8ee7496ab689b362095277abe3bd83005a7301dc323f6ae8725abadef5f7c436", kill_on_drop: false }`
[INFO] [stdout] 8ee7496ab689b362095277abe3bd83005a7301dc323f6ae8725abadef5f7c436
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/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" "+c2e32f1c9652b13ed99608599c1e855462f421f3" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 75723e25887705512f0af27e6050934a3ba7720d56fbb073507a244a84ef72e1
[INFO] running `Command { std: "docker" "start" "-a" "75723e25887705512f0af27e6050934a3ba7720d56fbb073507a244a84ef72e1", 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.23s
[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:52:13.209824Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting commit index advancement test
[INFO] [stdout] 2025-11-11T06:52:13.209954Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:52:13.210151Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting election timeout ranges test
[INFO] [stdout] 2025-11-11T06:52:13.210192Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.210293Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting detailed election process test for visualization
[INFO] [stdout] 2025-11-11T06:52:13.210309Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.210708Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader election test with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.210738Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.210951Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting heartbeat maintenance test
[INFO] [stdout] 2025-11-11T06:52:13.210977Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.211029Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.211070Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.211081Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.211092Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.211126Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.211130Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting log replication test
[INFO] [stdout] 2025-11-11T06:52:13.211142Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.211161Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.211184Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] test raft::events::tests::test_event_creation ... ok
[INFO] [stdout] 2025-11-11T06:52:13.211371Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.211396Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.211408Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] test raft::events::tests::test_event_broadcaster ... ok
[INFO] [stdout] 2025-11-11T06:52:13.211420Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.211441Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] test raft::events::tests::test_event_deduplication ... ok
[INFO] [stdout] 2025-11-11T06:52:13.211472Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.211496Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] test raft::events::tests::test_event_deduplication_time_window ... ok
[INFO] [stdout] 2025-11-11T06:52:13.211733Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting normal cluster operation test
[INFO] [stdout] 2025-11-11T06:52:13.211761Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.211809Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting proposal consensus flow test for visualization
[INFO] [stdout] 2025-11-11T06:52:13.211836Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.211888Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.211953Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.211979Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.211994Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.212001Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.212073Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.212083Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.212094Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.212104Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.212107Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.212147Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.212164Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.212178Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.212189Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.212199Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.212215Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:52:13.212224Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting concurrent proposals test
[INFO] [stdout] 2025-11-11T06:52:13.212239Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.212248Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.212251Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting heartbeat failure detection test
[INFO] [stdout] 2025-11-11T06:52:13.212263Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.212268Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.212305Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.212507Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.212539Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.212550Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.212560Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.212581Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned for timeout testing
[INFO] [stdout] 2025-11-11T06:52:13.212615Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.212658Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.212687Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.212037Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:52:13.212769Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.212797Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.212820Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.212844Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] test raft::events::tests::test_event_serialization ... ok
[INFO] [stdout] 2025-11-11T06:52:13.212870Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.212890Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:52:13.213042Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.213079Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.213090Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.213101Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.213122Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for natural election
[INFO] [stdout] 2025-11-11T06:52:13.213134Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.213201Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.213258Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.213295Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.213344Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for stable leadership
[INFO] [stdout] 2025-11-11T06:52:13.213388Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.213442Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.213513Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.213538Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader election test with 5 nodes
[INFO] [stdout] 2025-11-11T06:52:13.213561Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:52:13.213780Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.213802Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.213812Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.213822Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.213831Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:52:13.213841Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.213861Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.213884Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.213922Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.213942Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.213961Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:52:13.213146Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.214026Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.214052Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.214375Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting leader forwarding test
[INFO] [stdout] 2025-11-11T06:52:13.214392Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:52:13.214464Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting split vote test with 4 nodes
[INFO] [stdout] 2025-11-11T06:52:13.214486Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 4 nodes
[INFO] [stdout] 2025-11-11T06:52:13.213215Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.214560Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.214578Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.214590Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.213138Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.214614Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election and heartbeat establishment
[INFO] [stdout] 2025-11-11T06:52:13.214642Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.214646Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.214664Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.214674Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.214673Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.214685Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:52:13.214675Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.214707Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.214744Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.214764Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.214766Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.214830Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting proposal rejection cases test
[INFO] [stdout] 2025-11-11T06:52:13.214862Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:13.215102Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.215140Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.215152Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.215163Z  INFO raft_poc::raft::simulation: ✅ All 3 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.215186Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:52:13.215210Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.215254Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.215291Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.215536Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.215575Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.215588Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.215599Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.215623Z  INFO raft_poc::raft::simulation: ✅ All 4 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.215646Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.215688Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.215735Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.215774Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.215851Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.215881Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.215892Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.215940Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:52:13.215968Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.215982Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node cluster spawned, waiting for leader election
[INFO] [stdout] 2025-11-11T06:52:13.216019Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.216064Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.216101Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.216132Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.216156Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:52:13.288336Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting network partition recovery test
[INFO] [stdout] 2025-11-11T06:52:13.288382Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 5 nodes
[INFO] [stdout] 2025-11-11T06:52:13.288646Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.288685Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.288696Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.289006Z  INFO raft_poc::raft::integration_tests::integration_tests: 🧪 Starting split vote resolution test
[INFO] [stdout] 2025-11-11T06:52:13.289045Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 4 nodes
[INFO] [stdout] 2025-11-11T06:52:13.289259Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:13.289283Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:13.289294Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:13.289303Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.289312Z  INFO raft_poc::raft::simulation: ✅ All 4 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.289323Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 4-node cluster spawned
[INFO] [stdout] 2025-11-11T06:52:13.289356Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.289391Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.289410Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.289426Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.289479Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 3
[INFO] [stdout] 2025-11-11T06:52:13.289493Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 4
[INFO] [stdout] 2025-11-11T06:52:13.289504Z  INFO raft_poc::raft::simulation: ✅ All 5 nodes spawned successfully
[INFO] [stdout] 2025-11-11T06:52:13.289516Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node cluster spawned, establishing stable leadership
[INFO] [stdout] 2025-11-11T06:52:13.289536Z  INFO raft_poc::raft::simulation: 🟢 Node 0 started as Follower node_id=0
[INFO] [stdout] 2025-11-11T06:52:13.289563Z  INFO raft_poc::raft::simulation: 🟢 Node 1 started as Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:13.289584Z  INFO raft_poc::raft::simulation: 🟢 Node 2 started as Follower node_id=2
[INFO] [stdout] 2025-11-11T06:52:13.289603Z  INFO raft_poc::raft::simulation: 🟢 Node 3 started as Follower node_id=3
[INFO] [stdout] 2025-11-11T06:52:13.289623Z  INFO raft_poc::raft::simulation: 🟢 Node 4 started as Follower node_id=4
[INFO] [stdout] 2025-11-11T06:52:15.212135Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Election period completed, checking for leader
[INFO] [stdout] 2025-11-11T06:52:15.212189Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Leader election test completed
[INFO] [stdout] 2025-11-11T06:52:15.212204Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command1' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.212266Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command2' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.212412Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'command3' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] test raft::integration_tests::integration_tests::test_leader_election_3_nodes ... ok
[INFO] [stdout] 2025-11-11T06:52:15.213066Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.213108Z  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:52:15.213328Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.213362Z  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:52:15.213575Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.213606Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.213627Z  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:52:15.213640Z  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:52:15.213651Z  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:52:15.214156Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.221193Z  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:52:15.258467Z  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:52:15.268108Z  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:52:15.268171Z  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:52:15.268185Z  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:52:15.273866Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 0 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.273948Z  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] 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:52:15.277490Z  INFO raft_poc::raft::simulation: 🎆 Creating cluster with 3 nodes
[INFO] [stdout] 2025-11-11T06:52:15.277749Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 0
[INFO] [stdout] 2025-11-11T06:52:15.277786Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 1
[INFO] [stdout] 2025-11-11T06:52:15.277798Z  INFO raft_poc::raft::simulation: 🚀 Spawning node 2
[INFO] [stdout] 2025-11-11T06:52:15.277813Z  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:52:15.315627Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_1' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.416088Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_2' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.517585Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_3' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.618075Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'test_commit_4' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.719167Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.719253Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.719280Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.719322Z  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:52:15.719363Z  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:52:15.735141Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.735224Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.735249Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.735279Z  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:52:15.735320Z  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:52:15.739109Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.739175Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.739196Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.739220Z  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:52:15.739255Z  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:52:15.756138Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.756222Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.756248Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.756274Z  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:52:15.756316Z  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:52:15.781178Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.781262Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.781285Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.781305Z  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:52:15.781337Z  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:52:15.839022Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.839110Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.839136Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.839166Z  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:52:15.839211Z  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:52:15.842094Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.842161Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.842183Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.842208Z  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:52:15.842242Z  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:52:15.878170Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.878249Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.878273Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:15.878294Z  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:52:15.878339Z  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:52:15.938335Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.938414Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.938437Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=1
[INFO] [stdout] 2025-11-11T06:52:15.938459Z  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:52:15.938493Z  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:52:15.953039Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=3
[INFO] [stdout] 2025-11-11T06:52:15.953118Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:15.953143Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=3
[INFO] [stdout] 2025-11-11T06:52:15.953167Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 3 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=3
[INFO] [stdout] 2025-11-11T06:52:15.953199Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:15.973158Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.973236Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.973259Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:52:15.973279Z  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:52:15.973317Z  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:52:16.066169Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.066249Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.066272Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.066293Z  INFO raft_poc::raft::simulation: 🗳️ ELECTION STARTED: Candidate 3 requesting votes from 4 nodes for term 1 (need 3/5 votes) node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.066327Z  INFO raft_poc::raft::simulation: 📤 VOTE REQUESTS SENT: RequestVote broadcasted to 4 nodes for election term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.073173Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.073260Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.073286Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.073311Z  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:52:16.073353Z  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:52:16.207168Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.207247Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.207270Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/3 votes) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.207291Z  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:52:16.207322Z  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:52:16.212872Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Submitting test proposal for consensus flow visualization
[INFO] [stdout] 2025-11-11T06:52:16.213984Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 First election completed, triggering manual election
[INFO] [stdout] 2025-11-11T06:52:16.214097Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_ELECTION_TIMEOUT' by Candidate 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.214686Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Election period completed for 5-node cluster
[INFO] [stdout] 2025-11-11T06:52:16.214725Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ 5-node leader election test completed
[INFO] [stdout] 2025-11-11T06:52:16.215070Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Simulating leader failure to test heartbeat failure detection
[INFO] [stdout] test raft::integration_tests::integration_tests::test_leader_election_5_nodes ... ok
[INFO] [stdout] 2025-11-11T06:52:16.215196Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_LEADER_FAILURE' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.215241Z  INFO raft_poc::raft::simulation: 👑 Received leader failure simulation command, state: Follower node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.215769Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing proposal submission to follower (should forward)
[INFO] [stdout] 2025-11-11T06:52:16.215861Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Observing heartbeat patterns
[INFO] [stdout] 2025-11-11T06:52:16.215961Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Submitting multiple concurrent proposals
[INFO] [stdout] 2025-11-11T06:52:16.216028Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_0' by Candidate 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.216756Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing systematic forwarding from each node
[INFO] [stdout] 2025-11-11T06:52:16.216790Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_0' to node 0
[INFO] [stdout] 2025-11-11T06:52:16.216840Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_0' by Candidate 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.296269Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Testing cluster behavior under stress (simulating partition scenarios)
[INFO] [stdout] 2025-11-11T06:52:16.369216Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_3' by Candidate 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.498228Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_PARTITION' by Candidate 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.517238Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_1' by Candidate 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.618167Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_1' to node 1
[INFO] [stdout] 2025-11-11T06:52:16.654166Z  WARN raft_poc::raft::simulation: ⏰ Election timeout! Current state: Follower, term: 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.654443Z  INFO raft_poc::raft::algorithm: 🗳️  Starting election for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.654597Z  INFO raft_poc::raft::algorithm: 🎯 Became candidate for term 1, voted for self (1/2 votes) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.654783Z  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:52:16.654846Z  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:52:16.720206Z  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:52:16.720304Z  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:52:16.720352Z  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:52:16.720377Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.720392Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.720412Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.720437Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.738122Z  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:52:16.738213Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_1' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.738244Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_4' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.738295Z  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:52:16.738324Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'CONCURRENT_PROPOSAL_2' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.738366Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/2 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.738387Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.738401Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.738417Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.738437Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.741066Z  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:52:16.741141Z  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:52:16.741174Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.741228Z  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:52:16.741245Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.741256Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.741265Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 1 transitioning Candidate → Leader (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.741293Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.757200Z  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:52:16.757377Z  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:52:16.757506Z  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:52:16.757585Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.757623Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.757671Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.757732Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.782174Z  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:52:16.782282Z  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:52:16.782320Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 2/2 votes for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.782340Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.782354Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.782370Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 1 transitioning Candidate → Leader (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.782390Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821099Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_2' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.821158Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'FORWARDING_TEST_2' from follower 2 to leader 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.821204Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_TEST_2' by Leader 1 (WILL PROCESS) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821220Z  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:52:16.821231Z  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:52:16.821246Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821254Z  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:52:16.821268Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821289Z  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:52:16.821302Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821309Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821318Z  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:52:16.821326Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821348Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.821366Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.821389Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.821398Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.821425Z  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:52:16.821439Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.821448Z  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:52:16.821456Z  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:52:16.839869Z  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:52:16.839969Z  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:52:16.840008Z  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:52:16.840041Z  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:52:16.840051Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.840063Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.840070Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.840085Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.844156Z  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:52:16.844285Z  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:52:16.844332Z  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:52:16.844388Z  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:52:16.844419Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 3! Now have 3/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.844450Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.844481Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 3 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.844509Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.844540Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.879758Z  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:52:16.879859Z  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:52:16.879921Z  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:52:16.879942Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.879956Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.879970Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.879992Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.939173Z  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:52:16.939259Z  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:52:16.939295Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 2/2 votes for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.939309Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.939322Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.939337Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 1 transitioning Candidate → Leader (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.939357Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.954195Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 0 granted vote to candidate 3 for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.954301Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 1 granted vote to candidate 3 for term 1 node_id=1
[INFO] [stdout] 2025-11-11T06:52:16.954335Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 2 granted vote to candidate 3 for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:16.954361Z  INFO raft_poc::raft::simulation: ✅ VOTE GRANTED: Node 4 granted vote to candidate 3 for term 1 node_id=4
[INFO] [stdout] 2025-11-11T06:52:16.954397Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 2/3 votes for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.954410Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 3/3 votes for term 1 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.954419Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.954432Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.954441Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 3 transitioning Candidate → Leader (term 1) node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.954461Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 3 node_id=3
[INFO] [stdout] 2025-11-11T06:52:16.974827Z  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:52:16.974951Z  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:52:16.975007Z  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:52:16.975037Z  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:52:16.975074Z  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:52:16.975112Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 1! Now have 2/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.975137Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 3! Now have 3/3 votes for term 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.975145Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.975158Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.975167Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:16.975188Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019718Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_2' to node 2
[INFO] [stdout] 2025-11-11T06:52:17.019825Z  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:52:17.019842Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'FORWARDING_FROM_NODE_2' from follower 2 to leader 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.019880Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_2' by Leader 0 (WILL PROCESS) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019918Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'FORWARDING_FROM_NODE_2' → pending proposal at index 1 (term 1) | Need 3/5 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019930Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'FORWARDING_FROM_NODE_2' accepted as pending proposal at index 1 (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019946Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019955Z  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:52:17.019970Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.019993Z  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:52:17.020008Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020018Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020030Z  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:52:17.020040Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020047Z  INFO raft_poc::raft::simulation: 📤 → Follower 3: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020057Z  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:52:17.020068Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 3 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020077Z  INFO raft_poc::raft::simulation: 📤 → Follower 4: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020088Z  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:52:17.020098Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 4 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.020128Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:17.020153Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:52:17.020187Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.020210Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.020241Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=3
[INFO] [stdout] 2025-11-11T06:52:17.020254Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=3
[INFO] [stdout] 2025-11-11T06:52:17.020284Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=4
[INFO] [stdout] 2025-11-11T06:52:17.020298Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=4
[INFO] [stdout] 2025-11-11T06:52:17.020334Z  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:52:17.075197Z  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:52:17.075307Z  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:52:17.075346Z  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:52:17.075374Z  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:52:17.075400Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'SIMULATE_PARTITION' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:17.075459Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 0! Now have 2/3 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.075486Z  INFO raft_poc::raft::algorithm: ✅ Vote granted from Node 3! Now have 3/3 votes for term 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.075496Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.075510Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 4 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.075519Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.075539Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.122026Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Proposal rejection testing completed
[INFO] [stdout] 2025-11-11T06:52:17.208189Z  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:52:17.208294Z  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:52:17.208335Z  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:52:17.208376Z  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:52:17.208394Z  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:52:17.208403Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.208416Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 3 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.208424Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 0 transitioning Candidate → Leader (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.208444Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 0 node_id=0
[INFO] [stdout] 2025-11-11T06:52:17.213854Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Log replication test completed
[INFO] [stdout] 2025-11-11T06:52:17.213925Z  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:52:17.217076Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Split vote scenario test period completed
[INFO] [stdout] 2025-11-11T06:52:17.217103Z  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:52:17.421036Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_3' to node 3
[INFO] [stdout] 2025-11-11T06:52:17.421128Z  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:52:17.421143Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'FORWARDING_FROM_NODE_3' from follower 3 to leader 0 node_id=3
[INFO] [stdout] 2025-11-11T06:52:17.656678Z  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:52:17.656780Z  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:52:17.656831Z  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:52:17.656844Z  INFO raft_poc::raft::algorithm: 👑 Became LEADER for term 1 with majority votes! node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.656857Z  INFO raft_poc::raft::algorithm: ❤️  Starting to send heartbeats to 2 followers node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.656865Z  INFO raft_poc::raft::simulation: 🚨 LEADER ELECTION SUCCESS: Node 2 transitioning Candidate → Leader (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.656884Z  INFO raft_poc::raft::simulation: 📡 EVENTS EMITTED: LeaderElected + StateChange events sent for new leader 2 node_id=2
[INFO] [stdout] 2025-11-11T06:52:17.822187Z  INFO raft_poc::raft::integration_tests::integration_tests: 📤 Submitted 'FORWARDING_FROM_NODE_4' to node 4
[INFO] [stdout] 2025-11-11T06:52:17.822285Z  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:52:17.822304Z  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:52:17.822999Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:17.823028Z  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:52:17.823041Z  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:52:17.823063Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.021830Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.021893Z  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:52:18.021954Z  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:52:18.021972Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 3/3 acks - ready to commit! node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.021987Z  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:52:18.021997Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'FORWARDING_FROM_NODE_2' committed to log at index 1 (term 1) | Acknowledged by: [0, 1, 2] node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.212969Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_0' by Follower 0 (WILL REJECT) node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.213020Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'normal_op_0' from follower 0 to leader 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.213058Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_0' by Leader 1 (WILL PROCESS) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213078Z  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=1
[INFO] [stdout] 2025-11-11T06:52:18.213098Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_0' accepted as pending proposal at index 1 (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213116Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213124Z  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:52:18.213137Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213166Z  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:52:18.213179Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213194Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213205Z  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:52:18.213215Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213246Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.213266Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.213298Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.213311Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.213345Z  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:52:18.213360Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.213370Z  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:52:18.213378Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'normal_op_0' committed to log at index 1 (term 1) | Acknowledged by: [1, 0] node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.215454Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Manual election completed
[INFO] [stdout] 2025-11-11T06:52:18.215487Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Detailed election process test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_election_process_detailed ... ok
[INFO] [stdout] 2025-11-11T06:52:18.233065Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 First proposal completed, submitting to different node
[INFO] [stdout] 2025-11-11T06:52:18.233199Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'TEST_FORWARDING_PROPOSAL' by Follower 1 (WILL REJECT) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.233234Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'TEST_FORWARDING_PROPOSAL' from follower 1 to leader 2 node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.233280Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'TEST_FORWARDING_PROPOSAL' by Leader 2 (WILL PROCESS) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233312Z  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=2
[INFO] [stdout] 2025-11-11T06:52:18.233327Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'TEST_FORWARDING_PROPOSAL' accepted as pending proposal at index 1 (term 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233344Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 1 (awaiting consensus) - STEP 2/4 node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233361Z  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:52:18.233376Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233411Z  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:52:18.233429Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233449Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 1 entries (0 committed + 1 pending) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233476Z  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:52:18.233498Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233529Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.233557Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:52:18.233594Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 2 with 1 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.233618Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 2 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:52:18.233673Z  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:52:18.233699Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 1 has 2/2 acks - ready to commit! node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.233710Z  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:52:18.233722Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'TEST_FORWARDING_PROPOSAL' committed to log at index 1 (term 1) | Acknowledged by: [2, 0] node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.290156Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Split vote resolution test period completed
[INFO] [stdout] 2025-11-11T06:52:18.290205Z  INFO raft_poc::raft::integration_tests::integration_tests: ✅ Split vote scenario test completed
[INFO] [stdout] test raft::integration_tests::integration_tests::test_split_vote_resolution ... ok
[INFO] [stdout] 2025-11-11T06:52:18.615233Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_2' by Follower 2 (WILL REJECT) node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.615290Z  INFO raft_poc::raft::simulation: 📤 FORWARDING: Command 'normal_op_2' from follower 2 to leader 1 node_id=2
[INFO] [stdout] 2025-11-11T06:52:18.722656Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Commit index advancement test completed
[INFO] [stdout] 2025-11-11T06:52:18.722701Z  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:52:19.023183Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 2 node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023232Z  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:52:19.023243Z  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:52:19.023261Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023324Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'FORWARDING_FROM_NODE_3' by Leader 0 (WILL PROCESS) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023338Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'FORWARDING_FROM_NODE_3' → pending proposal at index 2 (term 1) | Need 3/5 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023348Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'FORWARDING_FROM_NODE_3' accepted as pending proposal at index 2 (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023361Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023368Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 4 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023380Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023395Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 0 → follower 1 (2 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023412Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023421Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023435Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 0 → follower 2 (2 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023444Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023452Z  INFO raft_poc::raft::simulation: 📤 → Follower 3: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023471Z  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:52:19.023481Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 3 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023489Z  INFO raft_poc::raft::simulation: 📤 → Follower 4: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023500Z  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:52:19.023510Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 4 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023529Z  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:52:19.023539Z  INFO raft_poc::raft::algorithm: 📋 STEP 1/4 - PROPOSAL CREATED: Command 'FORWARDING_FROM_NODE_4' → pending proposal at index 2 (term 1) | Need 3/5 acks for consensus node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023547Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'FORWARDING_FROM_NODE_4' accepted as pending proposal at index 2 (term 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023559Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023565Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 4 followers node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023573Z  INFO raft_poc::raft::simulation: 📤 → Follower 1: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023586Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 0 → follower 1 (2 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023594Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 1 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023602Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023615Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 0 → follower 2 (2 entries) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023622Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023629Z  INFO raft_poc::raft::simulation: 📤 → Follower 3: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023638Z  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:52:19.023646Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 3 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023653Z  INFO raft_poc::raft::simulation: 📤 → Follower 4: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023663Z  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:52:19.023671Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 4 successfully node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.023704Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 2 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.023724Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.023747Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 2 entries (term: 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.023759Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.023782Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 2 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.023792Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.023806Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 2 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.023815Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.023834Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=3
[INFO] [stdout] 2025-11-11T06:52:19.023844Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=3
[INFO] [stdout] 2025-11-11T06:52:19.023858Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=3
[INFO] [stdout] 2025-11-11T06:52:19.023939Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=3
[INFO] [stdout] 2025-11-11T06:52:19.023972Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=4
[INFO] [stdout] 2025-11-11T06:52:19.023984Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=4
[INFO] [stdout] 2025-11-11T06:52:19.024000Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 0 with 1 entries (term: 1) node_id=4
[INFO] [stdout] 2025-11-11T06:52:19.024009Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 0 → SUCCESS (ACK) node_id=4
[INFO] [stdout] 2025-11-11T06:52:19.024037Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 1 acknowledged proposal 2 → 2/3 acks (waiting for more...) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.122658Z  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:52:19.213144Z  INFO raft_poc::raft::integration_tests::integration_tests: ⏱️ Election occurred within 6 seconds
[INFO] [stdout] 2025-11-11T06:52:19.213188Z  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:52:19.225052Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225115Z  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:52:19.225130Z  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:52:19.225151Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225206Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_1' by Leader 1 (WILL PROCESS) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225223Z  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=1
[INFO] [stdout] 2025-11-11T06:52:19.225234Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_1' accepted as pending proposal at index 2 (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225249Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225258Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225272Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225291Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 1 → follower 0 (2 entries) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225310Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225321Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225332Z  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:52:19.225343Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225381Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ClientCommandReceived 'normal_op_2' by Leader 1 (WILL PROCESS) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225394Z  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=1
[INFO] [stdout] 2025-11-11T06:52:19.225403Z  INFO raft_poc::raft::simulation: 🔄 CONSENSUS FLOW START: Client command 'normal_op_2' accepted as pending proposal at index 2 (term 1) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225416Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: LogEntryProposed for proposal 2 (awaiting consensus) - STEP 2/4 node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225425Z  INFO raft_poc::raft::simulation: 📤 STEP 2/4 - REPLICATING: Broadcasting AppendEntries with proposal 2 to 2 followers node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225439Z  INFO raft_poc::raft::simulation: 📤 → Follower 0: Sending AppendEntries with 2 entries (1 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225454Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: 2 LogEntryProposed events from leader 1 → follower 0 (2 entries) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225466Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 0 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225484Z  INFO raft_poc::raft::simulation: 📤 → Follower 2: Sending AppendEntries with 1 entries (1 committed + 1 pending) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225497Z  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:52:19.225507Z  INFO raft_poc::raft::simulation: ✅ AppendEntries sent to follower 2 successfully node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225544Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 2 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.225563Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.225588Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 2 entries (term: 1) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.225600Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=0
[INFO] [stdout] 2025-11-11T06:52:19.225626Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.225637Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.225655Z  INFO raft_poc::raft::simulation: 📥 RECEIVED: AppendEntries from leader 1 with 1 entries (term: 1) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.225666Z  INFO raft_poc::raft::simulation: 📤 RESPONDING: AppendEntries response to leader 1 → SUCCESS (ACK) node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.225697Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 0 acknowledged proposal 2 → 2/2 acks (CONSENSUS ACHIEVED!) node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225711Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 2 has 2/2 acks - ready to commit! node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225722Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 2 achieved consensus → moving to committed log node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.225731Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'normal_op_2' committed to log at index 2 (term 1) | Acknowledged by: [1, 0] node_id=1
[INFO] [stdout] 2025-11-11T06:52:19.235203Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=2
[INFO] [stdout] 2025-11-11T06:52:19.235261Z  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:52:19.235276Z  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:52:19.235297Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=2
[INFO] [stdout] 2025-11-11T06:52:20.025203Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:20.025262Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 1 → leader 0 for proposal 2 (2/3 acks, consensus: false) node_id=0
[INFO] [stdout] 2025-11-11T06:52:20.025305Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 1 acknowledged proposal 2 → 2/3 acks (waiting for more...) node_id=0
[INFO] [stdout] 2025-11-11T06:52:20.227178Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 0 node_id=1
[INFO] [stdout] 2025-11-11T06:52:20.227238Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 0 → leader 1 for proposal 2 (2/2 acks, consensus: true) node_id=1
[INFO] [stdout] 2025-11-11T06:52:20.227252Z  INFO raft_poc::raft::simulation: 🎉 PROPOSALS COMMITTED: 1 new entries added to committed log (index 2 → 2) node_id=1
[INFO] [stdout] 2025-11-11T06:52:20.227274Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ReplicationCompleted for 1 entries achieving consensus node_id=1
[INFO] [stdout] 2025-11-11T06:52:20.238119Z  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:52:20.473064Z  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:52:20.700678Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Partition simulation completed, observing recovery
[INFO] [stdout] 2025-11-11T06:52:20.817522Z  INFO raft_poc::raft::integration_tests::integration_tests: 🔍 Normal operation test completed
[INFO] [stdout] 2025-11-11T06:52:20.817567Z  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:52:21.027192Z  INFO raft_poc::raft::simulation: 📊 Found 1 consensus ACK(s) to emit for follower 1 node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.027252Z  INFO raft_poc::raft::simulation: 📡 EVENT EMITTED: ConsensusAckReceived from follower 1 → leader 0 for proposal 2 (2/3 acks, consensus: false) node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.027296Z  INFO raft_poc::raft::algorithm: 📝 STEP 3/4 - ACK RECEIVED: Follower 2 acknowledged proposal 2 → 3/3 acks (CONSENSUS ACHIEVED!) node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.027315Z  INFO raft_poc::raft::algorithm: 🎯 CONSENSUS DETECTED: Proposal 2 has 3/3 acks - ready to commit! node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.027328Z  INFO raft_poc::raft::algorithm: 🎯 STEP 4/4 - COMMITTING: Proposal 2 achieved consensus → moving to committed log node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.027338Z  INFO raft_poc::raft::algorithm: ✅ CONSENSUS FLOW COMPLETE: Command 'FORWARDING_FROM_NODE_4' committed to log at index 2 (term 1) | Acknowledged by: [0, 1, 2] node_id=0
[INFO] [stdout] 2025-11-11T06:52:21.217632Z  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:52:21.238044Z  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:52:22.216621Z  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:52:23.701508Z  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.50s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "75723e25887705512f0af27e6050934a3ba7720d56fbb073507a244a84ef72e1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "75723e25887705512f0af27e6050934a3ba7720d56fbb073507a244a84ef72e1", kill_on_drop: false }`
[INFO] [stdout] 75723e25887705512f0af27e6050934a3ba7720d56fbb073507a244a84ef72e1