diff --git a/src/api/client_server/alias.rs b/src/api/client_server/alias.rs index 550cb656..045d1174 100644 --- a/src/api/client_server/alias.rs +++ b/src/api/client_server/alias.rs @@ -10,7 +10,7 @@ use ruma::{ }, OwnedRoomAliasId, OwnedServerName, }; -use tracing::{debug, info, warn}; +use tracing::debug; use crate::{debug_info, debug_warn, services, Error, Result, Ruma}; diff --git a/src/service/rooms/spaces/mod.rs b/src/service/rooms/spaces/mod.rs index 714da443..25bf3c22 100644 --- a/src/service/rooms/spaces/mod.rs +++ b/src/service/rooms/spaces/mod.rs @@ -30,7 +30,7 @@ use ruma::{ OwnedRoomId, OwnedServerName, RoomId, ServerName, UInt, UserId, }; use tokio::sync::Mutex; -use tracing::{debug, error, info, warn}; +use tracing::{debug, error, warn}; use crate::{debug_info, services, Error, Result}; diff --git a/src/service/sending/mod.rs b/src/service/sending/mod.rs index 86676d58..32a7409a 100644 --- a/src/service/sending/mod.rs +++ b/src/service/sending/mod.rs @@ -272,7 +272,7 @@ impl Service { }); } - #[tracing::instrument(skip(self), name = "sender")] + #[tracing::instrument(skip_all, name = "sender")] async fn handler(&self) -> Result<()> { let receiver = self.receiver.lock().await; diff --git a/src/service/sending/send.rs b/src/service/sending/send.rs index d6bd36d2..9859cc32 100644 --- a/src/service/sending/send.rs +++ b/src/service/sending/send.rs @@ -14,9 +14,9 @@ use ruma::{ }, OwnedServerName, ServerName, }; -use tracing::{debug, error, trace, warn}; +use tracing::{debug, error, trace}; -use crate::{debug_error, debug_warn, services, Error, Result}; +use crate::{debug_error, debug_info, debug_warn, services, Error, Result}; /// Wraps either an literal IP address plus port, or a hostname plus complement /// (colon-plus-port if it was specified). @@ -300,6 +300,7 @@ async fn resolve_actual_destination(destination: &'_ ServerName) -> Result<(FedD Ok((actual_destination, hostname.into_uri_string())) } +#[tracing::instrument(skip_all, name = "well-known")] async fn request_well_known(destination: &str) -> Result> { if !services() .globals @@ -320,22 +321,22 @@ async fn request_well_known(destination: &str) -> Result> { .send() .await; - trace!("Well known response: {:?}", response); + trace!("response: {:?}", response); if let Err(e) = &response { - debug!("Well known error: {e:?}"); + debug!("error: {e:?}"); return Ok(None); } let response = response?; if !response.status().is_success() { - debug!("Well known response not 2XX"); + debug!("response not 2XX"); return Ok(None); } let text = response.text().await?; - trace!("Well known response text: {:?}", text); + trace!("response text: {:?}", text); if text.len() >= 12288 { - debug!("Well known response contains junk"); + debug_warn!("response contains junk"); return Ok(None); } @@ -348,13 +349,15 @@ async fn request_well_known(destination: &str) -> Result> { .unwrap_or_default(); if ruma_identifiers_validation::server_name::validate(m_server).is_err() { - debug!("Well known response content missing or invalid"); + debug_error!("response content missing or invalid"); return Ok(None); } + debug_info!("{:?} found at {:?}", destination, m_server); Ok(Some(m_server.to_owned())) } +#[tracing::instrument(skip_all, name = "ip")] async fn query_and_cache_override(overname: &'_ str, hostname: &'_ str, port: u16) -> Result<()> { match services() .globals @@ -362,8 +365,11 @@ async fn query_and_cache_override(overname: &'_ str, hostname: &'_ str, port: u1 .lookup_ip(hostname.to_owned()) .await { + Err(e) => handle_resolve_error(&e), Ok(override_ip) => { - trace!("Caching result of {:?} overriding {:?}", hostname, overname); + if hostname != overname { + debug_info!("{:?} overriden by {:?}", overname, hostname); + } services() .globals .resolver @@ -374,13 +380,10 @@ async fn query_and_cache_override(overname: &'_ str, hostname: &'_ str, port: u1 Ok(()) }, - Err(e) => { - debug!("Got {:?} for {:?} to override {:?}", e.kind(), hostname, overname); - handle_resolve_error(&e) - }, } } +#[tracing::instrument(skip_all, name = "srv")] async fn query_srv_record(hostname: &'_ str) -> Result> { fn handle_successful_srv(srv: &SrvLookup) -> Option { srv.iter().next().map(|result| { @@ -421,11 +424,11 @@ fn handle_resolve_error(e: &ResolveError) -> Result<()> { ResolveErrorKind::Io { .. } => { - debug_error!("DNS IO error: {e}"); + error!("{e}"); Err(Error::Error(e.to_string())) }, _ => { - debug!("DNS protocol error: {e}"); + debug_error!("{e}"); Ok(()) }, } @@ -514,19 +517,17 @@ fn validate_destination(destination: &ServerName) -> Result<()> { validate_destination_ip_literal(destination)?; } - trace!("Destination ServerName is valid"); Ok(()) } fn validate_destination_ip_literal(destination: &ServerName) -> Result<()> { + trace!("Destination is an IP literal, checking against IP range denylist.",); debug_assert!( destination.is_ip_literal() || !IPAddress::is_valid(destination.host()), "Destination is not an IP literal." ); - debug!("Destination is an IP literal, checking against IP range denylist.",); - let ip = IPAddress::parse(destination.host()).map_err(|e| { - debug_warn!("Failed to parse IP literal from string: {}", e); + debug_error!("Failed to parse IP literal from string: {}", e); Error::BadServerResponse("Invalid IP address") })?; @@ -558,6 +559,7 @@ fn add_port_to_hostname(destination_str: &str) -> FedDest { None => (destination_str, ":8448"), Some(pos) => destination_str.split_at(pos), }; + FedDest::Named(host.to_owned(), port.to_owned()) } diff --git a/src/utils/debug.rs b/src/utils/debug.rs index 6c1093a0..32a8cf3f 100644 --- a/src/utils/debug.rs +++ b/src/utils/debug.rs @@ -1,14 +1,23 @@ +/// Log event at given level in debug-mode (when debug-assertions are enabled). +/// In release mode it becomes DEBUG level, and possibly subject to elision. +#[macro_export] +macro_rules! debug_event { + ( $level:expr, $($x:tt)+ ) => { + if cfg!(debug_assertions) { + tracing::event!( $level, $($x)+ ); + } else { + tracing::debug!( $($x)+ ); + } + } +} + /// Log message at the ERROR level in debug-mode (when debug-assertions are /// enabled). In release mode it becomes DEBUG level, and possibly subject to /// elision. #[macro_export] macro_rules! debug_error { ( $($x:tt)+ ) => { - if cfg!(debug_assertions) { - error!( $($x)+ ); - } else { - debug!( $($x)+ ); - } + $crate::debug_event!(tracing::Level::ERROR, $($x)+ ); } } @@ -18,11 +27,7 @@ macro_rules! debug_error { #[macro_export] macro_rules! debug_warn { ( $($x:tt)+ ) => { - if cfg!(debug_assertions) { - warn!( $($x)+ ); - } else { - debug!( $($x)+ ); - } + $crate::debug_event!(tracing::Level::WARN, $($x)+ ); } } @@ -32,10 +37,6 @@ macro_rules! debug_warn { #[macro_export] macro_rules! debug_info { ( $($x:tt)+ ) => { - if cfg!(debug_assertions) { - info!( $($x)+ ); - } else { - debug!( $($x)+ ); - } + $crate::debug_event!(tracing::Level::INFO, $($x)+ ); } }