From 8f4349793e058be9be8784921b3b081e30d278a2 Mon Sep 17 00:00:00 2001 From: houseme Date: Tue, 7 Jul 2026 22:40:24 +0800 Subject: [PATCH] fix(ecstore): log peer offline/online transitions for console reporting (#4367) A node could show OFFLINE in the console with zero logs explaining why (rustfs/backlog#888, reported in rustfs#4304): the consecutive-failure threshold crossing in handle_server_info_failure marked the peer offline silently, the per-call warnings only existed on the observing node and never named the transition, and the PeerRestClient offline flag plus its background recovery monitor ran without any start/success log. Logging-only change, no behavior change: - handle_server_info_failure / handle_storage_info_failure: WARN event="peer_marked_offline" exactly once at the threshold crossing (later failures while already offline stay DEBUG), and DEBUG event="peer_probe_failure" while returning cached state below the threshold. - update_server_info_cache / update_storage_info_cache: INFO event="peer_recovered_online" when a probe succeeds after the peer had been reported offline. - PeerRestClient::mark_offline_and_spawn_recovery: WARN event="peer_connection_marked_offline" when the offline flag is first set (guarded by the recovery_running CAS so repeated failures do not spam), and INFO event="peer_connection_recovered" with the attempt count when connectivity is restored. An "offline then back" episode now leaves a complete, correlatable trace: N probe failures -> peer_marked_offline -> recovery monitor -> peer_recovered_online. Verification: - cargo test -p rustfs-ecstore --lib (notification + peer_rest suites) - make pre-commit Ref: rustfs/backlog#888, rustfs#4304 Co-authored-by: heihutu --- .../src/cluster/rpc/peer_rest_client.rs | 18 +++++- .../ecstore/src/services/notification_sys.rs | 64 +++++++++++++++++++ 2 files changed, 80 insertions(+), 2 deletions(-) diff --git a/crates/ecstore/src/cluster/rpc/peer_rest_client.rs b/crates/ecstore/src/cluster/rpc/peer_rest_client.rs index 7279e84b4..81a306194 100644 --- a/crates/ecstore/src/cluster/rpc/peer_rest_client.rs +++ b/crates/ecstore/src/cluster/rpc/peer_rest_client.rs @@ -53,7 +53,7 @@ use tokio::{net::TcpStream, time::Duration}; use tonic::Request; use tonic::service::interceptor::InterceptedService; use tonic::transport::Channel; -use tracing::{debug, warn}; +use tracing::{debug, info, warn}; pub const PEER_RESTSIGNAL: &str = "signal"; pub const PEER_RESTSUB_SYS: &str = "sub-sys"; @@ -184,15 +184,29 @@ impl PeerRestClient { let offline = Arc::clone(&self.offline); let recovery_running = Arc::clone(&self.recovery_running); let span = Self::recovery_monitor_span(&grid_host); + // The offline flag and its recovery are the silent half of + // rustfs/backlog#888: log the monitor's start and its success so an + // "offline then back" episode leaves a trace on the observing node. + warn!( + event = "peer_connection_marked_offline", + grid_host = %self.grid_host, + "peer RPC connection marked offline after a network-like failure; starting background recovery monitor" + ); super::spawn_background_monitor(span, async move { let mut delay = get_drive_active_check_interval(); let connect_timeout = get_drive_active_check_timeout(); - for _ in 0..PEER_REST_RECOVERY_MAX_ATTEMPTS { + for attempt in 1..=PEER_REST_RECOVERY_MAX_ATTEMPTS { tokio::time::sleep(delay).await; if Self::perform_connectivity_check(&grid_host, connect_timeout).await.is_ok() { offline.store(false, Ordering::Release); recovery_running.store(false, Ordering::Release); + info!( + event = "peer_connection_recovered", + grid_host = %grid_host, + attempts = attempt, + "peer connectivity restored by background recovery monitor" + ); return; } diff --git a/crates/ecstore/src/services/notification_sys.rs b/crates/ecstore/src/services/notification_sys.rs index a0e68a75d..e9a4b8de2 100644 --- a/crates/ecstore/src/services/notification_sys.rs +++ b/crates/ecstore/src/services/notification_sys.rs @@ -1024,10 +1024,28 @@ fn handle_peer_failure( if let Some(ref cached) = c.last_storage_info && c.storage_failures < CONSECUTIVE_FAILURE_THRESHOLD { + debug!( + event = "peer_probe_failure", + peer = host, + probe = "storage_info", + consecutive_failures = c.storage_failures, + threshold = CONSECUTIVE_FAILURE_THRESHOLD, + "peer storage_info probe failed; returning cached state until the offline threshold is reached" + ); return Some(cached.clone()); } if c.storage_failures >= CONSECUTIVE_FAILURE_THRESHOLD { + if c.storage_failures == CONSECUTIVE_FAILURE_THRESHOLD { + warn!( + event = "peer_marked_offline", + peer = host, + probe = "storage_info", + consecutive_failures = c.storage_failures, + threshold = CONSECUTIVE_FAILURE_THRESHOLD, + "reporting peer disks offline after consecutive storage_info failures" + ); + } return Some(StorageInfo { disks: get_offline_disks(host, endpoints), ..Default::default() @@ -1049,6 +1067,15 @@ fn update_storage_info_cache(cache: Option<&Mutex>, host: &str, poisoned.into_inner() } }; + if c.storage_failures >= CONSECUTIVE_FAILURE_THRESHOLD { + info!( + event = "peer_recovered_online", + peer = host, + probe = "storage_info", + consecutive_failures = c.storage_failures, + "peer storage_info probe succeeded again; peer disks reported online" + ); + } c.last_storage_info = Some(info.clone()); c.storage_failures = 0; } @@ -1076,10 +1103,39 @@ fn handle_server_info_failure( if let Some(ref cached) = c.last_server_info && c.server_failures < CONSECUTIVE_FAILURE_THRESHOLD { + debug!( + event = "peer_probe_failure", + peer = host, + consecutive_failures = c.server_failures, + threshold = CONSECUTIVE_FAILURE_THRESHOLD, + "peer server_info probe failed; returning cached state until the offline threshold is reached" + ); return cached.clone(); } if c.server_failures >= CONSECUTIVE_FAILURE_THRESHOLD { + // Log the transition exactly once (at the crossing) so the console's + // "node offline" verdict has a matching WARN in the observer's logs + // (rustfs/backlog#888: nodes were marked offline with no log naming + // the transition). Later failures while already offline stay at DEBUG + // to avoid repeating the warning every probe cycle. + if c.server_failures == CONSECUTIVE_FAILURE_THRESHOLD { + warn!( + event = "peer_marked_offline", + peer = host, + consecutive_failures = c.server_failures, + threshold = CONSECUTIVE_FAILURE_THRESHOLD, + "marking peer offline for admin/console reporting after consecutive server_info failures; \ + a background recovery probe will restore it automatically once reachable" + ); + } else { + debug!( + event = "peer_still_offline", + peer = host, + consecutive_failures = c.server_failures, + "peer server_info probe failed while peer is already reported offline" + ); + } return offline_server_properties(host, endpoints); } @@ -1098,6 +1154,14 @@ fn update_server_info_cache(cache: Option<&Mutex>, host: &str, i poisoned.into_inner() } }; + if c.server_failures >= CONSECUTIVE_FAILURE_THRESHOLD { + info!( + event = "peer_recovered_online", + peer = host, + consecutive_failures = c.server_failures, + "peer server_info probe succeeded again; peer is back online for admin/console reporting" + ); + } c.last_server_info = Some(info.clone()); c.server_failures = 0; }