diff --git a/src/client/lifecycle.rs b/src/client/lifecycle.rs index 3a90751a7..eb3936363 100644 --- a/src/client/lifecycle.rs +++ b/src/client/lifecycle.rs @@ -289,7 +289,8 @@ impl Client { } } else { wacore::telemetry::connect("ok"); - let unexpected_disconnect = if self.read_messages_loop().await.is_err() { + let loop_result = self.read_messages_loop().await; + let unexpected_disconnect = if let Err(e) = loop_result { // Check intentional_reconnect AFTER read loop exits — reconnect() // sets this flag while the loop is running, so it must be read here. if self.expected_disconnect.load(Ordering::Relaxed) @@ -298,9 +299,12 @@ impl Client { debug!("Message loop exited during expected disconnect."); false } else { - warn!( - "Message loop exited with an error. Will attempt to reconnect if enabled." - ); + // read_messages_loop already logged the cause at the right level + // (info for a clean server recycle, warn for a real transport + // error), so keep this at debug to avoid re-flagging a benign + // reconnect as an error. Still treated as an unexpected + // disconnect for the event dispatch + reconnect below. + debug!("Message loop exited, will reconnect if enabled: {e:#}"); true } } else if self.expected_disconnect.load(Ordering::Relaxed) { diff --git a/src/client/node_io.rs b/src/client/node_io.rs index 4558895a5..6a6f3d620 100644 --- a/src/client/node_io.rs +++ b/src/client/node_io.rs @@ -123,17 +123,27 @@ impl Client { }, Ok(crate::transport::TransportEvent::Disconnected(reason)) => { if !self.expected_disconnect.load(Ordering::Relaxed) { - debug!("Transport disconnected unexpectedly: {reason}"); + // Classify the level: a routine server recycle (clean EOF / + // normal close) is logged quietly, but a real transport error + // stays at WARN so it's never hidden behind reconnect noise. + if reason.is_clean_shutdown() { + info!("Connection closed by server ({reason}); reconnecting."); + } else { + warn!("Transport disconnected: {reason}; reconnecting."); + } return Err(anyhow::anyhow!("Transport disconnected: {reason}")); } else { debug!("Transport disconnected as expected: {reason}"); return Ok(()); } } - // Event channel closed (no DisconnectReason available). + // Event channel closed (no DisconnectReason available) — the + // transport task ended without reporting why. No reason means we + // can't prove it was a clean recycle, so it stays loud (WARN), + // matching the conservative `Unknown` rule in is_clean_shutdown. Err(_) => { if !self.expected_disconnect.load(Ordering::Relaxed) { - debug!("Transport event channel closed unexpectedly."); + warn!("Transport event channel closed; reconnecting."); return Err(anyhow::anyhow!("Transport event channel closed")); } else { return Ok(()); @@ -330,7 +340,9 @@ impl Client { if self.expected_disconnect.load(Ordering::Relaxed) { debug!("Received , expected disconnect."); } else { - warn!("Received , treating as disconnect."); + // A bare is the server cleanly ending the stream + // (a recycle). We reconnect, so this is routine, not an error. + info!("Received (server stream end); reconnecting."); } self.notify_connection_shutdown(); return; diff --git a/src/keepalive.rs b/src/keepalive.rs index 9fd360668..07169a94b 100644 --- a/src/keepalive.rs +++ b/src/keepalive.rs @@ -45,6 +45,22 @@ fn classify_keepalive_error(e: &IqError) -> KeepaliveResult { } } +/// Whether a keepalive ping error is just collateral of a teardown already +/// being handled elsewhere (the connection is gone, so the ping had nowhere to +/// go) rather than a genuine failure the keepalive surfaced first. +/// +/// Used ONLY to pick the log level. It must stay narrower than the +/// `FatalFailure` set: Socket/EncryptSend/ClientState/EncodeError are also +/// fatal for control flow, but they mean the socket or send pipeline broke +/// while we still believed we were connected — a real failure that the +/// keepalive may be the first (or only) thing to observe, so it must stay loud. +fn is_benign_teardown(e: &IqError) -> bool { + matches!( + e, + IqError::NotConnected | IqError::Disconnected(_) | IqError::InternalChannelClosed + ) +} + impl Client { /// Sends a keepalive ping and updates the server time offset from /// the pong's `t` attribute using RTT-adjusted midpoint calculation. @@ -90,7 +106,17 @@ impl Client { } Err(e) => { let result = classify_keepalive_error(&e); - warn!(target: "Client/Keepalive", "Keepalive ping failed: {e:?}"); + // Log level is keyed on benign-teardown, NOT on FatalFailure: only + // an already-gone connection (NotConnected/Disconnected/channel + // closed, handled elsewhere) is quiet collateral. A broken + // socket/send pipeline is also fatal for control flow but is a real + // failure the keepalive may see first, so it stays loud — as do all + // transient failures. + if is_benign_teardown(&e) { + debug!(target: "Client/Keepalive", "Keepalive skipped, connection already closing: {e:?}"); + } else { + warn!(target: "Client/Keepalive", "Keepalive ping failed: {e:?}"); + } result } } @@ -247,7 +273,7 @@ impl Client { #[cfg(test)] mod tests { use super::*; - use crate::socket::error::SocketError; + use crate::socket::error::{EncryptSendError, SocketError}; use wacore_binary::builder::NodeBuilder; #[test] @@ -315,5 +341,43 @@ mod tests { ); } + // Happy path: the connection was already gone, so a failed ping is just + // teardown collateral and is logged quietly. + #[test] + fn benign_teardown_errors_are_quiet() { + assert!(is_benign_teardown(&IqError::NotConnected)); + assert!(is_benign_teardown(&IqError::InternalChannelClosed)); + let node = NodeBuilder::new("disconnect").build(); + assert!(is_benign_teardown(&IqError::Disconnected(node))); + } + + // Bad path: a broken socket/send pipeline or an encode failure is fatal for + // control flow but is a REAL failure (we still thought we were connected), so + // it must NOT be treated as benign — it has to stay loud. Transient failures + // stay loud too. This is the guard against the keepalive ping silently + // swallowing the first sign of a real connection/send break. + #[test] + fn real_failures_are_never_treated_as_benign() { + assert!(!is_benign_teardown(&IqError::Socket( + SocketError::SocketClosed + ))); + assert!(!is_benign_teardown(&IqError::EncryptSend( + EncryptSendError::transport(anyhow::anyhow!("broken pipe")) + ))); + assert!(!is_benign_teardown(&IqError::EncodeError(anyhow::anyhow!( + "encode failed" + )))); + assert!(!is_benign_teardown(&IqError::Timeout)); + assert!(!is_benign_teardown(&IqError::ParseError(anyhow::anyhow!( + "bad response" + )))); + assert!(!is_benign_teardown(&IqError::ServerError { + code: 500, + text: "internal".to_string(), + error_type: None, + backoff: None, + })); + } + // ms_since, is_dead_socket, and constants tests live in wacore::protocol::keepalive } diff --git a/wacore/src/net.rs b/wacore/src/net.rs index f733b7ed0..45e3e3499 100644 --- a/wacore/src/net.rs +++ b/wacore/src/net.rs @@ -39,6 +39,30 @@ impl std::fmt::Display for DisconnectReason { } } +impl DisconnectReason { + /// Whether this is a benign, server-initiated stream recycle (the normal + /// WhatsApp reconnect path) rather than a transport-level error. + /// + /// Used only to pick a log level: a clean shutdown is logged quietly (the + /// reconnect is routine), while everything else stays loud so a genuine + /// transport failure is never hidden behind reconnect noise. Deliberately + /// conservative — anything ambiguous returns `false` (stays loud): a read/IO + /// error, an abnormal close code, or an unreported reason. + pub fn is_clean_shutdown(&self) -> bool { + match self { + // EOF with no Close frame is how the WA server recycles a connection. + Self::StreamEnded => true, + // A Close frame with a normal / going-away / no code is graceful; any + // other code (protocol/server error, restart, etc.) stays loud. + Self::ServerClose { code, .. } => matches!(code, None | Some(1000) | Some(1001)), + // A transport read/IO error is a real failure — never quiet. + Self::ReadError(_) => false, + // Unknown reason: stay loud, don't assume it was benign. + Self::Unknown => false, + } + } +} + /// An event produced by the transport layer. #[derive(Debug, Clone)] pub enum TransportEvent { @@ -176,3 +200,55 @@ pub trait HttpClient: Send + Sync { )) } } + +#[cfg(test)] +mod tests { + use super::DisconnectReason; + + // Happy paths: benign server-initiated recycles must classify as clean so + // their reconnect is logged quietly. + #[test] + fn clean_shutdowns_are_classified_clean() { + assert!(DisconnectReason::StreamEnded.is_clean_shutdown()); + assert!( + DisconnectReason::ServerClose { + code: Some(1000), + reason: String::new() + } + .is_clean_shutdown() + ); + assert!( + DisconnectReason::ServerClose { + code: Some(1001), + reason: "going away".to_string() + } + .is_clean_shutdown() + ); + assert!( + DisconnectReason::ServerClose { + code: None, + reason: String::new() + } + .is_clean_shutdown() + ); + } + + // Bad paths: a real transport error, an abnormal close code, or an unreported + // reason must NOT be classified clean — they have to stay loud so genuine + // failures are never hidden behind reconnect noise. + #[test] + fn real_errors_are_never_classified_clean() { + assert!(!DisconnectReason::ReadError("connection reset".to_string()).is_clean_shutdown()); + assert!(!DisconnectReason::Unknown.is_clean_shutdown()); + for code in [1002u16, 1006, 1011, 1012, 1013, 3000, 4000] { + assert!( + !DisconnectReason::ServerClose { + code: Some(code), + reason: String::new() + } + .is_clean_shutdown(), + "close code {code} must not be treated as a clean shutdown" + ); + } + } +}