From 541fa2d2f7f24f07f96426c0215892e46fb1c695 Mon Sep 17 00:00:00 2001 From: Jason Volk Date: Sun, 14 Apr 2024 03:54:54 -0700 Subject: [PATCH] tweak various log levels and messages Signed-off-by: Jason Volk --- src/service/rooms/timeline/mod.rs | 6 ++-- src/service/sending/mod.rs | 2 +- src/service/sending/send.rs | 59 ++++++++++++++----------------- src/utils/error.rs | 6 ++-- 4 files changed, 32 insertions(+), 41 deletions(-) diff --git a/src/service/rooms/timeline/mod.rs b/src/service/rooms/timeline/mod.rs index 89b1b009..62d7ccf8 100644 --- a/src/service/rooms/timeline/mod.rs +++ b/src/service/rooms/timeline/mod.rs @@ -31,7 +31,7 @@ use ruma::{ use serde::Deserialize; use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use tokio::sync::{Mutex, MutexGuard, RwLock}; -use tracing::{error, info, warn}; +use tracing::{debug, error, info, warn}; use super::state_compressor::CompressedStateEvent; use crate::{ @@ -1156,7 +1156,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, pdu))] + #[tracing::instrument(skip(self, pdu, pub_key_map))] pub async fn backfill_pdu( &self, origin: &ServerName, pdu: Box, pub_key_map: &RwLock>>, @@ -1241,7 +1241,7 @@ impl Service { } drop(mutex_lock); - info!("Prepended backfill pdu"); + debug!("Prepended backfill pdu"); Ok(()) } } diff --git a/src/service/sending/mod.rs b/src/service/sending/mod.rs index a83555fa..91853a4f 100644 --- a/src/service/sending/mod.rs +++ b/src/service/sending/mod.rs @@ -822,7 +822,7 @@ async fn handle_events_kind_normal( .map(|response| { for pdu in response.pdus { if pdu.1.is_err() { - warn!("Failed to send to {}: {:?}", dest, pdu); + warn!("error for {} from remote: {:?}", pdu.0, pdu.1); } } kind.clone() diff --git a/src/service/sending/send.rs b/src/service/sending/send.rs index ebd01570..5090db99 100644 --- a/src/service/sending/send.rs +++ b/src/service/sending/send.rs @@ -15,7 +15,7 @@ use ruma::{ }, OwnedServerName, ServerName, }; -use tracing::{debug, info, warn}; +use tracing::{debug, trace, warn}; use crate::{services, Error, Result}; @@ -59,7 +59,7 @@ where } if destination.is_ip_literal() || IPAddress::is_valid(destination.host()) { - info!( + debug!( "Destination {} is an IP literal, checking against IP range denylist.", destination ); @@ -83,10 +83,10 @@ where } } - info!("IP literal {} is allowed.", destination); + debug!("IP literal {} is allowed.", destination); } - debug!("Preparing to send request to {destination}"); + trace!("Preparing to send request to {destination}"); let mut write_destination_to_cache = false; @@ -182,11 +182,11 @@ where } let reqwest_request = reqwest::Request::try_from(http_request)?; - + let method = reqwest_request.method().clone(); let url = reqwest_request.url().clone(); if let Some(url_host) = url.host_str() { - debug!("Checking request URL for IP"); + trace!("Checking request URL for IP"); if let Ok(ip) = IPAddress::parse(url_host) { let cidr_ranges_s = services().globals.ip_range_denylist().to_vec(); let mut cidr_ranges: Vec = Vec::new(); @@ -203,15 +203,15 @@ where } } - debug!("Sending request to {destination} at {url}"); + debug!("Sending request {} {}", method, url); let response = client.execute(reqwest_request).await; - debug!("Received response from {destination} at {url}"); + trace!("Received resonse {} {}", method, url); match response { Ok(mut response) => { // reqwest::Response -> http::Response conversion - debug!("Checking response destination's IP"); + trace!("Checking response destination's IP"); if let Some(remote_addr) = response.remote_addr() { if let Ok(ip) = IPAddress::parse(remote_addr.ip().to_string()) { let cidr_ranges_s = services().globals.ip_range_denylist().to_vec(); @@ -240,18 +240,15 @@ where .expect("http::response::Builder is usable"), ); - debug!("Getting response bytes from {destination}"); + trace!("Waiting for response body"); let body = response.bytes().await.unwrap_or_else(|e| { - info!("server error {}", e); + debug!("server error {}", e); Vec::new().into() }); // TODO: handle timeout - debug!("Got response bytes from {destination}"); if !status.is_success() { debug!( - "Response not successful\n{} {}: {}", - url, - status, + "Got {status:?} for {method} {url}: {}", String::from_utf8_lossy(&body) .lines() .collect::>() @@ -264,7 +261,7 @@ where .expect("reqwest body is valid http body"); if status.is_success() { - debug!("Parsing response bytes from {destination}"); + debug!("Got {status:?} for {method} {url}"); let response = T::IncomingResponse::try_from_http_response(http_response); if response.is_ok() && write_destination_to_cache { services() @@ -276,11 +273,10 @@ where } response.map_err(|e| { - info!("Invalid 200 response from {} on: {} {}", &destination, url, e); + debug!("Invalid 200 response for {} {}", url, e); Error::BadServerResponse("Server returned bad 200 response.") }) } else { - debug!("Returning error from {destination}"); Err(Error::FederationError( destination.to_owned(), RumaError::from_http_response(http_response), @@ -306,7 +302,7 @@ where e.url() ); } else { - info!("Could not send request to {} at {}: {}", destination, actual_destination_str, e); + debug!("Could not send request to {} at {}: {}", destination, actual_destination_str, e); } Err(e.into()) @@ -338,7 +334,7 @@ fn add_port_to_hostname(destination_str: &str) -> FedDest { /// specification #[tracing::instrument(skip_all, name = "resolve")] async fn resolve_actual_destination(destination: &'_ ServerName) -> (FedDest, FedDest) { - debug!("Finding actual destination for {destination}"); + trace!("Finding actual destination for {destination}"); let destination_str = destination.as_str().to_owned(); let mut hostname = destination_str.clone(); let actual_destination = match get_ip_with_port(&destination_str) { @@ -355,7 +351,7 @@ async fn resolve_actual_destination(destination: &'_ ServerName) -> (FedDest, Fe FedDest::Named(host.to_owned(), port.to_owned()) } else { - debug!("Requesting well known for {destination}"); + trace!("Requesting well known for {destination}"); if let Some(delegated_hostname) = request_well_known(destination.as_str()).await { debug!("3: A .well-known file is available"); hostname = add_port_to_hostname(&delegated_hostname).into_uri_string(); @@ -370,7 +366,7 @@ async fn resolve_actual_destination(destination: &'_ ServerName) -> (FedDest, Fe FedDest::Named(host.to_owned(), port.to_owned()) } else { - debug!("Delegated hostname has no port in this branch"); + trace!("Delegated hostname has no port in this branch"); if let Some(hostname_override) = query_srv_record(&delegated_hostname).await { debug!("3.3: SRV lookup successful"); @@ -396,9 +392,9 @@ async fn resolve_actual_destination(destination: &'_ ServerName) -> (FedDest, Fe }, } } else { - debug!("4: No .well-known or an error occured"); + trace!("4: No .well-known or an error occured"); if let Some(hostname_override) = query_srv_record(&destination_str).await { - debug!("4: SRV record found"); + debug!("4: No .well-known; SRV record found"); let force_port = hostname_override.port(); query_and_cache_override(&hostname, &hostname_override.hostname(), force_port.unwrap_or(8448)) @@ -410,7 +406,7 @@ async fn resolve_actual_destination(destination: &'_ ServerName) -> (FedDest, Fe add_port_to_hostname(&hostname) } } else { - debug!("5: No SRV record found"); + debug!("4: No .well-known; 5: No SRV record found"); query_and_cache_override(&destination_str, &destination_str, 8448).await; add_port_to_hostname(&destination_str) } @@ -444,7 +440,7 @@ async fn query_and_cache_override(overname: &'_ str, hostname: &'_ str, port: u1 .await { Ok(override_ip) => { - debug!("Caching result of {:?} overriding {:?}", hostname, overname); + trace!("Caching result of {:?} overriding {:?}", hostname, overname); services() .globals @@ -485,7 +481,7 @@ async fn query_srv_record(hostname: &'_ str) -> Option { lookup_srv(&first_hostname) .or_else(|_| { - debug!("Querying deprecated _matrix SRV record for host {:?}", hostname); + trace!("Querying deprecated _matrix SRV record for host {:?}", hostname); lookup_srv(&second_hostname) }) .and_then(|srv_lookup| async move { Ok(handle_successful_srv(&srv_lookup)) }) @@ -513,18 +509,15 @@ async fn request_well_known(destination: &str) -> Option { .get(&format!("https://{destination}/.well-known/matrix/server")) .send() .await; - debug!("Got well known response"); - debug!("Well known response: {:?}", response); + trace!("Well known response: {:?}", response); if let Err(e) = &response { debug!("Well known error: {e:?}"); return None; } let text = response.ok()?.text().await; - - debug!("Got well known response text"); - debug!("Well known response text: {:?}", text); + trace!("Well known response text: {:?}", text); if text.as_ref().ok()?.len() > 10000 { debug!( @@ -535,7 +528,7 @@ async fn request_well_known(destination: &str) -> Option { } let body: serde_json::Value = serde_json::from_str(&text.ok()?).ok()?; - debug!("serde_json body of well known text: {}", body); + trace!("serde_json body of well known text: {}", body); Some(body.get("m.server")?.as_str()?.to_owned()) } diff --git a/src/utils/error.rs b/src/utils/error.rs index 949bdff4..fb48b792 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -9,7 +9,7 @@ use ruma::{ OwnedServerName, }; use thiserror::Error; -use tracing::{error, info}; +use tracing::{debug, error}; use ErrorKind::{ Forbidden, GuestAccessForbidden, LimitExceeded, MissingToken, NotFound, ThreepidAuthFailed, ThreepidDenied, TooLarge, Unauthorized, Unknown, UnknownToken, Unrecognized, UserDeactivated, WrongRoomKeysVersion, @@ -110,7 +110,6 @@ impl Error { } let message = format!("{self}"); - let (kind, status_code) = match self { Self::BadRequest(kind, _) => ( kind.clone(), @@ -142,8 +141,7 @@ impl Error { _ => (Unknown, StatusCode::INTERNAL_SERVER_ERROR), }; - info!("Returning an error: {status_code}: {message}"); - + debug!("Returning an error: {status_code}: {message}"); RumaResponse(UiaaResponse::MatrixError(RumaError { body: ErrorBody::Standard { kind,