From 964ca662a93f30aebf2ad101cfd297f64599d769 Mon Sep 17 00:00:00 2001 From: Tyson George Date: Wed, 7 Oct 2026 04:58:54 -0400 Subject: [PATCH] fix: keep whole SIP messages out of WARN logs Some WARN records carried a whole SIP message, with the From/To/Contact URIs, display names and any body: - the dialog layer's "failed to send request" (send_prack_request and send_dialog_request) printed the full request; - the WebSocket transport's "Error parsing SIP message" printed the raw text frame; - the "bye skipped" WARN of ClientInviteDialog, InviteDialog and ServerInviteDialog printed the dialog state with Debug, which for Early, WaitAck and Confirmed includes the whole response; the returned error did the same. The send failure now logs the method at WARN and the request at DEBUG. The WebSocket parse failure logs the frame length; the frame is already logged at INFO when it is received. The BYE paths use the Display of DialogState (dialog id and state name). --- src/dialog/client_dialog.rs | 4 +- src/dialog/dialog.rs | 10 +- src/dialog/invite_dialog.rs | 4 +- src/dialog/server_dialog.rs | 4 +- src/dialog/tests/mod.rs | 1 + src/dialog/tests/test_warn_logs.rs | 195 +++++++++++++++++++++++++++++ src/transport/websocket.rs | 2 +- 7 files changed, 209 insertions(+), 11 deletions(-) create mode 100644 src/dialog/tests/test_warn_logs.rs diff --git a/src/dialog/client_dialog.rs b/src/dialog/client_dialog.rs index c4b3fd8c..1582466c 100644 --- a/src/dialog/client_dialog.rs +++ b/src/dialog/client_dialog.rs @@ -162,11 +162,11 @@ impl ClientInviteDialog { if !self.inner.is_terminated() { warn!( dialog_id = %self.id(), - state = ?self.state(), + state = %self.state(), "bye skipped: dialog not confirmed" ); return Err(crate::Error::Error(format!( - "dialog {} cannot send BYE in state {:?}", + "dialog {} cannot send BYE in state {}", self.id(), self.state() ))); diff --git a/src/dialog/dialog.rs b/src/dialog/dialog.rs index 9f62fc2a..611e95fd 100644 --- a/src/dialog/dialog.rs +++ b/src/dialog/dialog.rs @@ -707,10 +707,11 @@ impl DialogInner { warn!( id = self.id.lock().to_string(), destination = tx.destination.as_ref().map(|d| d.to_string()).as_deref(), - "failed to send request error: {}\n{}", - e, - tx.original + method = %method, + "failed to send request error: {}", + e ); + debug!(id = self.id.lock().to_string(), req = %tx.original, "request that failed to send"); return Err(e); } } @@ -1153,10 +1154,11 @@ impl DialogInner { warn!( id = self.id.lock().to_string(), destination = tx.destination.as_ref().map(|d| d.to_string()).as_deref(), - req = %tx.original, + method = %method, "failed to send request error: {}", e ); + debug!(id = self.id.lock().to_string(), req = %tx.original, "request that failed to send"); return Err(e); } } diff --git a/src/dialog/invite_dialog.rs b/src/dialog/invite_dialog.rs index 72a3587b..4cd6ea2e 100644 --- a/src/dialog/invite_dialog.rs +++ b/src/dialog/invite_dialog.rs @@ -429,11 +429,11 @@ impl InviteDialog { if !self.inner.is_terminated() { warn!( dialog_id = %self.id(), - state = ?self.state(), + state = %self.state(), "bye skipped: dialog not confirmed or waiting ack" ); return Err(crate::Error::Error(format!( - "dialog {} cannot send BYE in state {:?}", + "dialog {} cannot send BYE in state {}", self.id(), self.state() ))); diff --git a/src/dialog/server_dialog.rs b/src/dialog/server_dialog.rs index 3456600f..e3ace560 100644 --- a/src/dialog/server_dialog.rs +++ b/src/dialog/server_dialog.rs @@ -356,11 +356,11 @@ impl ServerInviteDialog { if !self.inner.is_terminated() { warn!( dialog_id = %self.id(), - state = ?self.state(), + state = %self.state(), "bye skipped: dialog not confirmed or waiting ack" ); return Err(crate::Error::Error(format!( - "dialog {} cannot send BYE in state {:?}", + "dialog {} cannot send BYE in state {}", self.id(), self.state() ))); diff --git a/src/dialog/tests/mod.rs b/src/dialog/tests/mod.rs index ead0ba64..bb4036dc 100644 --- a/src/dialog/tests/mod.rs +++ b/src/dialog/tests/mod.rs @@ -15,3 +15,4 @@ mod test_server_dialog; mod test_session_id; mod test_sub_pub; mod test_uas_ack_timeout; +mod test_warn_logs; diff --git a/src/dialog/tests/test_warn_logs.rs b/src/dialog/tests/test_warn_logs.rs new file mode 100644 index 00000000..ecd4c6f4 --- /dev/null +++ b/src/dialog/tests/test_warn_logs.rs @@ -0,0 +1,195 @@ +//! WARN records carry metadata only; the whole SIP message is logged below WARN. +use crate::dialog::dialog::{DialogInner, DialogState}; +use crate::dialog::{client_dialog::ClientInviteDialog, invite_dialog::InviteDialog}; +use crate::dialog::{server_dialog::ServerInviteDialog, DialogId}; +use crate::sip::{Request, SipMessage, Uri}; +use crate::transaction::{endpoint::TargetLocator, key::TransactionRole}; +use crate::transport::{SipAddr, TransportLayer}; +use std::sync::{Arc, Mutex}; +use tokio::sync::mpsc::unbounded_channel; +use tracing::{field::Field, span, Event, Level, Metadata, Subscriber}; + +const MARKER: &str = "private-marker"; + +/// Records every event as (level, " field=value ..."). +#[derive(Clone, Default)] +struct Capture(Arc>>); + +impl Subscriber for Capture { + fn enabled(&self, _: &Metadata<'_>) -> bool { + true + } + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, event: &Event<'_>) { + let mut line = String::new(); + event.record(&mut |f: &Field, v: &dyn std::fmt::Debug| { + line.push_str(&format!(" {}={:?}", f.name(), v)) + }); + self.0 + .lock() + .unwrap() + .push((*event.metadata().level(), line)); + } + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} +} + +impl Capture { + fn lines(&self, level: Level, needle: &str) -> Vec { + let records = self.0.lock().unwrap(); + let hits = records + .iter() + .filter(|(l, s)| *l == level && s.contains(needle)); + hits.map(|(_, s)| s.clone()).collect() + } +} + +/// Fails every lookup, so `Transaction::send` returns an error. +struct NoRoute; + +#[async_trait::async_trait] +impl TargetLocator for NoRoute { + async fn locate(&self, _: &Uri) -> crate::Result { + Err(crate::Error::Error("no route".to_string())) + } +} + +/// A request or response whose From carries `MARKER`. +fn message(start_line: &str, cseq: &str) -> SipMessage { + let text = format!( + "{start_line}\r\nVia: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bKwarn\r\nCSeq: {cseq}\r\n\ + From: \"{MARKER}\" ;tag=a\r\n\ + To: ;tag=b\r\nCall-ID: warn-call\r\n\r\n" + ); + SipMessage::try_from(text.as_str()).unwrap() +} + +fn request(method: &str, cseq: u32) -> Request { + let start_line = format!("{method} sip:bob@127.0.0.1:5999 SIP/2.0"); + match message(&start_line, &format!("{cseq} {method}")) { + SipMessage::Request(req) => req, + other => panic!("{other:?}"), + } +} + +/// A UAC dialog on an endpoint whose every request send fails. +fn dialog() -> crate::Result> { + let endpoint = crate::EndpointBuilder::new() + .with_transport_layer(TransportLayer::new(Default::default())) + .with_target_locator(Box::new(NoRoute)) + .build(); + let id = DialogId { + call_id: "warn-call".to_string(), + local_tag: "a".to_string(), + remote_tag: "b".to_string(), + }; + let (state_tx, _) = unbounded_channel(); + let (tu_tx, _) = unbounded_channel(); + let invite = request("INVITE", 1); + let inner = DialogInner::new( + TransactionRole::Client, + id, + invite, + endpoint.inner.clone(), + state_tx, + None, + None, + tu_tx, + )?; + Ok(Arc::new(inner)) +} + +#[tokio::test] +async fn test_failed_request_send_warns_without_the_request() -> crate::Result<()> { + let capture = Capture::default(); + let _guard = tracing::subscriber::set_default(capture.clone()); + let inner = dialog()?; + + // send_dialog_request, then send_prack_request. + assert!(inner.do_request(request("INFO", 2)).await.is_err()); + assert!(inner.send_prack_request(request("PRACK", 3)).await.is_err()); + + let warns = capture.lines(Level::WARN, "failed to send request"); + assert_eq!(warns.len(), 2, "{warns:?}"); + assert!(warns.iter().all(|w| !w.contains(MARKER)), "{warns:?}"); + assert!(warns[0].contains("method=INFO") && warns[1].contains("method=PRACK")); + let debugs = capture.lines(Level::DEBUG, "request that failed to send"); + assert_eq!(debugs.len(), 2, "{debugs:?}"); + assert!(debugs.iter().all(|d| d.contains(MARKER)), "{debugs:?}"); + Ok(()) +} + +#[tokio::test] +async fn test_bye_in_early_state_warns_without_the_response() -> crate::Result<()> { + let capture = Capture::default(); + let _guard = tracing::subscriber::set_default(capture.clone()); + let inner = dialog()?; + let SipMessage::Response(ringing) = message("SIP/2.0 180 Ringing", "1 INVITE") else { + unreachable!() + }; + inner.transition(DialogState::Early(inner.id.lock().clone(), ringing))?; + + let errors = [ + ClientInviteDialog { + inner: inner.clone(), + } + .bye() + .await, + InviteDialog { + inner: inner.clone(), + } + .bye() + .await, + ServerInviteDialog { inner }.bye().await, + ]; + for e in errors { + let e = e.expect_err("BYE in Early must fail").to_string(); + assert!(e.contains("(Early)") && !e.contains(MARKER), "{e}"); + } + let warns = capture.lines(Level::WARN, "bye skipped"); + assert_eq!(warns.len(), 3, "{warns:?}"); + assert!(warns.iter().all(|w| !w.contains(MARKER)), "{warns:?}"); + Ok(()) +} + +#[cfg(feature = "websocket")] +#[tokio::test] +async fn test_websocket_parse_failure_warns_without_the_message() -> crate::Result<()> { + use crate::transport::{stream::StreamConnection, websocket::WebSocketConnection}; + use futures::SinkExt; + use tokio_tungstenite::tungstenite::{handshake::server::Response, Message}; + + let capture = Capture::default(); + let _guard = tracing::subscriber::set_default(capture.clone()); + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await?; + let addr = listener.local_addr()?; + tokio::spawn(async move { + let (stream, _) = listener.accept().await.unwrap(); + let sip = |_: &_, mut resp: Response| { + let headers = resp.headers_mut(); + headers.insert("sec-websocket-protocol", "sip".parse().unwrap()); + Ok(resp) + }; + let mut ws = tokio_tungstenite::accept_hdr_async(stream, sip) + .await + .unwrap(); + let text = format!("NOT SIP \r\n\r\n"); + ws.send(Message::Text(text.into())).await.unwrap(); + ws.close(None).await.ok(); + }); + let remote = SipAddr::new(crate::sip::transport::Transport::Ws, addr.into()); + let conn = WebSocketConnection::connect(&remote, None).await?; + conn.serve_loop(unbounded_channel().0).await?; + + let warns = capture.lines(Level::WARN, "Error parsing SIP message"); + assert_eq!(warns.len(), 1, "{warns:?}"); + assert!(!warns[0].contains(MARKER), "{warns:?}"); + assert!(warns[0].contains("len=")); + // Still logged, below WARN, when it is received. + assert!(!capture.lines(Level::INFO, MARKER).is_empty()); + Ok(()) +} diff --git a/src/transport/websocket.rs b/src/transport/websocket.rs index ee6ed530..250ae5c5 100644 --- a/src/transport/websocket.rs +++ b/src/transport/websocket.rs @@ -340,7 +340,7 @@ impl StreamConnection for WebSocketConnection { } } Err(e) => { - warn!(error = %e, src = %remote_addr, raw_message = ?text.as_str(), "Error parsing SIP message"); + warn!(error = %e, src = %remote_addr, len = text.len(), "Error parsing SIP message"); } } }