From 41c6fc8029f2150566d6b373fc6756403a305390 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Fri, 13 Dec 2024 20:07:10 -0800 Subject: [PATCH 01/12] replace our DisplayWithSources with wee-woo It's the same thing except with a nice extension trait. --- Cargo.lock | 7 +++++++ Cargo.toml | 1 + src/error.rs | 30 +----------------------------- src/main.rs | 9 ++------- 4 files changed, 11 insertions(+), 36 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d7ccc059..c18ece69 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -947,6 +947,7 @@ dependencies = [ "tracing-opentelemetry", "tracing-subscriber", "trust-dns-resolver", + "wee-woo", "xdg", ] @@ -3871,6 +3872,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "wee-woo" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "005e18f8367a2e0e375c29dd4d266c97e7590ec9d64bb05dc5af054a555eda05" + [[package]] name = "weezl" version = "0.1.8" diff --git a/Cargo.toml b/Cargo.toml index c9754bb9..82ee8554 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -144,6 +144,7 @@ tracing-flame = "0.2.0" tracing-opentelemetry = "0.25.0" tracing-subscriber = { version = "0.3.19", features = ["env-filter", "json"] } trust-dns-resolver = "0.23.2" +wee-woo = "0.1.0" xdg = "2.5.2" [target.'cfg(unix)'.dependencies] diff --git a/src/error.rs b/src/error.rs index 49cf7307..ed8c2208 100644 --- a/src/error.rs +++ b/src/error.rs @@ -1,39 +1,11 @@ //! Error handling facilities -use std::{fmt, iter, path::PathBuf}; +use std::path::PathBuf; use thiserror::Error; use crate::config::ListenConfig; -/// Formats an [`Error`][0] and its [`source`][1]s with a separator -/// -/// [0]: std::error::Error -/// [1]: std::error::Error::source -pub(crate) struct DisplayWithSources<'a> { - /// The error (and its sources) to write - pub(crate) error: &'a dyn std::error::Error, - - /// Separator to write between the original error and subsequent sources - pub(crate) infix: &'static str, -} - -impl fmt::Display for DisplayWithSources<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "{}", self.error)?; - - let mut source = self.error.source(); - - source - .into_iter() - .chain(iter::from_fn(|| { - source = source.and_then(std::error::Error::source); - source - })) - .try_for_each(|source| write!(f, "{}{source}", self.infix)) - } -} - /// Top-level errors // Missing docs are allowed here since that kind of information should be // encoded in the error messages themselves anyway. diff --git a/src/main.rs b/src/main.rs index 8f4268a1..a0930e73 100644 --- a/src/main.rs +++ b/src/main.rs @@ -8,6 +8,7 @@ use clap::Parser; #[cfg(all(not(target_env = "msvc"), feature = "jemalloc"))] use tikv_jemallocator::Jemalloc; use tracing::{error, info}; +use wee_woo::ErrorExt; mod api; mod cli; @@ -100,13 +101,7 @@ async fn main() -> ExitCode { return ExitCode::SUCCESS; }; - eprintln!( - "Error: {}", - error::DisplayWithSources { - error: &e, - infix: "\n Caused by: " - } - ); + eprintln!("Error: {}", e.display_with_sources("\n Caused by: ")); ExitCode::FAILURE } From bc5f31b3a2daa942227386b588047484e753ebcf Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 01:01:32 -0800 Subject: [PATCH 02/12] add observability prelude module The reason to do a wildcard import of the prelude instead of something like // src/observability/prelude.rs pub(crate) use tracing::*; // elsewhere use crate::observability::prelude as o; o::warn!("something"); is that we can't import traits like tracing::Instrument that way. I'm generally not a fan of wildcard imports, but I think it can be okay when it's a module in the same crate. There aren't really an backwards compatibility hazards because it's your own code. --- src/observability.rs | 2 ++ src/observability/prelude.rs | 14 ++++++++++++++ 2 files changed, 16 insertions(+) create mode 100644 src/observability/prelude.rs diff --git a/src/observability.rs b/src/observability.rs index 44e06c91..9f3bca7a 100644 --- a/src/observability.rs +++ b/src/observability.rs @@ -38,6 +38,8 @@ use crate::{ utils::error::Result, }; +pub(crate) mod prelude; + /// Globally accessible metrics state pub(crate) static METRICS: LazyLock = LazyLock::new(Metrics::new); diff --git a/src/observability/prelude.rs b/src/observability/prelude.rs new file mode 100644 index 00000000..63d39bca --- /dev/null +++ b/src/observability/prelude.rs @@ -0,0 +1,14 @@ +//! Common tracing-related items intended to be wildcard imported in most +//! modules: +//! +//! ``` +//! use crate::observability::prelude::*; +//! ``` +//! +//! This avoids diff churn in the imports when adding/removing log statements. +//! +//! [`tracing`] is re-exported as `t`, to avoid name collisions. +#![allow(unused)] + +pub(crate) use tracing as t; +pub(crate) use tracing::Instrument; From 5fca67054e8ab049bd3dd315e5b6ade62fd62bf2 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 00:49:56 -0800 Subject: [PATCH 03/12] switch all tracing imports to observability::prelude --- src/api/appservice_server.rs | 13 +- src/api/client_server/account.rs | 14 +- src/api/client_server/context.rs | 7 +- src/api/client_server/directory.rs | 17 +- src/api/client_server/keys.rs | 9 +- src/api/client_server/media.rs | 50 +++-- src/api/client_server/membership.rs | 66 +++--- src/api/client_server/profile.rs | 10 +- src/api/client_server/room.rs | 14 +- src/api/client_server/session.rs | 22 +- src/api/client_server/state.rs | 18 +- src/api/client_server/sync.rs | 6 +- src/api/client_server/sync/msc3575.rs | 15 +- src/api/client_server/sync/v3.rs | 38 ++-- src/api/ruma_wrapper/axum.rs | 25 ++- src/api/server_server.rs | 127 +++++------ src/cli/check_config.rs | 6 +- src/cli/serve.rs | 57 +++-- src/database.rs | 41 ++-- src/database/abstraction/rocksdb.rs | 23 +- src/database/abstraction/sqlite.rs | 7 +- src/database/key_value/account_data.rs | 9 +- src/database/key_value/globals.rs | 3 +- src/database/key_value/media.rs | 3 +- src/database/key_value/rooms/alias.rs | 11 +- src/database/key_value/rooms/auth_chain.rs | 3 +- src/database/key_value/rooms/directory.rs | 13 +- .../key_value/rooms/edus/read_receipt.rs | 11 +- src/database/key_value/rooms/metadata.rs | 5 +- src/database/key_value/rooms/outlier.rs | 7 +- src/database/key_value/rooms/search.rs | 7 +- src/database/key_value/rooms/short.rs | 13 +- src/database/key_value/rooms/state_cache.rs | 41 ++-- src/database/key_value/rooms/timeline.rs | 3 +- src/database/key_value/sending.rs | 3 +- src/database/key_value/users.rs | 14 +- src/error.rs | 6 +- src/main.rs | 12 +- src/observability.rs | 11 +- src/observability/prelude.rs | 1 - src/service/admin.rs | 26 ++- src/service/appservice.rs | 14 +- src/service/globals.rs | 26 ++- src/service/media.rs | 49 +++-- src/service/pdu.rs | 27 ++- src/service/pusher.rs | 23 +- src/service/rooms/auth_chain.rs | 25 ++- src/service/rooms/edus/typing.rs | 21 +- src/service/rooms/event_handler.rs | 197 ++++++++++-------- src/service/rooms/lazy_loading.rs | 10 +- src/service/rooms/pdu_metadata.rs | 16 +- src/service/rooms/spaces.rs | 31 ++- src/service/rooms/state.rs | 24 +-- src/service/rooms/state_accessor.rs | 50 ++--- src/service/rooms/state_cache.rs | 66 +++--- src/service/rooms/state_compressor.rs | 8 +- src/service/rooms/timeline.rs | 57 ++--- src/service/sending.rs | 62 +++--- src/service/uiaa.rs | 6 +- src/utils.rs | 8 +- src/utils/error.rs | 9 +- src/utils/on_demand_hashmap.rs | 33 ++- src/utils/proxy_protocol.rs | 10 +- 63 files changed, 824 insertions(+), 735 deletions(-) diff --git a/src/api/appservice_server.rs b/src/api/appservice_server.rs index 117d1914..49383f22 100644 --- a/src/api/appservice_server.rs +++ b/src/api/appservice_server.rs @@ -5,15 +5,14 @@ use ruma::api::{ appservice::Registration, IncomingResponse, MatrixVersion, OutgoingRequest, SendAccessToken, }; -use tracing::warn; -use crate::{services, utils, Error, Result}; +use crate::{observability::prelude::*, services, utils, Error, Result}; /// Sends a request to an appservice /// /// Only returns None if there is no url specified in the appservice /// registration file -#[tracing::instrument(skip(request))] +#[t::instrument(skip(request))] pub(crate) async fn send_request( registration: Registration, request: T, @@ -63,7 +62,7 @@ where .execute(reqwest_request) .await .inspect_err(|error| { - warn!( + t::warn!( %error, appservice = registration.id, %destination, @@ -84,12 +83,12 @@ where // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - warn!(%error, "Server error"); + t::warn!(%error, "Server error"); Vec::new().into() }); if status != 200 { - warn!( + t::warn!( appservice = %destination, %status, %url, @@ -108,7 +107,7 @@ where ); response.map(Some).map_err(|error| { - warn!( + t::warn!( %error, appservice = %destination, %url, diff --git a/src/api/client_server/account.rs b/src/api/client_server/account.rs index d660c6ba..eead6252 100644 --- a/src/api/client_server/account.rs +++ b/src/api/client_server/account.rs @@ -16,10 +16,12 @@ use ruma::{ }, push, UserId, }; -use tracing::{info, warn}; use super::{DEVICE_ID_LENGTH, SESSION_ID_LENGTH, TOKEN_LENGTH}; -use crate::{api::client_server, services, utils, Ar, Error, Ra, Result}; +use crate::{ + api::client_server, observability::prelude::*, services, utils, Ar, Error, + Ra, Result, +}; const RANDOM_USER_ID_LENGTH: usize = 10; @@ -276,7 +278,7 @@ pub(crate) async fn register_route( body.initial_device_display_name.clone(), )?; - info!(%user_id, "New user registered on this server"); + t::info!(%user_id, "New user registered on this server"); if body.appservice_info.is_none() && !is_guest { services().admin.send_message(RoomMessageEventContent::notice_plain( format!("New user {user_id} registered on this server."), @@ -292,7 +294,7 @@ pub(crate) async fn register_route( { services().admin.make_user_admin(&user_id, displayname).await?; - warn!( + t::warn!( %user_id, "Granting admin privileges to the first user", ); @@ -375,7 +377,7 @@ pub(crate) async fn change_password_route( } } - info!(user_id = %sender_user, "User changed their password"); + t::info!(user_id = %sender_user, "User changed their password"); services().admin.send_message(RoomMessageEventContent::notice_plain( format!("User {sender_user} changed their password."), )); @@ -455,7 +457,7 @@ pub(crate) async fn deactivate_route( // Remove devices and mark account as deactivated services().users.deactivate_account(sender_user)?; - info!(user_id = %sender_user, "User deactivated their account"); + t::info!(user_id = %sender_user, "User deactivated their account"); services().admin.send_message(RoomMessageEventContent::notice_plain( format!("User {sender_user} deactivated their account."), )); diff --git a/src/api/client_server/context.rs b/src/api/client_server/context.rs index ba803454..6aa11b9f 100644 --- a/src/api/client_server/context.rs +++ b/src/api/client_server/context.rs @@ -7,9 +7,8 @@ use ruma::{ events::StateEventType, uint, }; -use tracing::error; -use crate::{services, Ar, Error, Ra, Result}; +use crate::{observability::prelude::*, services, Ar, Error, Ra, Result}; /// # `GET /_matrix/client/r0/rooms/{roomId}/context` /// @@ -165,14 +164,14 @@ pub(crate) async fn get_context_route( if event_type != StateEventType::RoomMember { let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; state.push(pdu.to_state_event()); } else if !lazy_load_enabled || lazy_loaded.contains(&state_key) { let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; state.push(pdu.to_state_event()); diff --git a/src/api/client_server/directory.rs b/src/api/client_server/directory.rs index ed95e034..86731348 100644 --- a/src/api/client_server/directory.rs +++ b/src/api/client_server/directory.rs @@ -26,10 +26,10 @@ use ruma::{ }, uint, ServerName, UInt, }; -use tracing::{error, info, warn}; use crate::{ - service::rooms::state::ExtractType, services, Ar, Error, Ra, Result, + observability::prelude::*, service::rooms::state::ExtractType, services, + Ar, Error, Ra, Result, }; /// # `POST /_matrix/client/r0/publicRooms` @@ -94,7 +94,7 @@ pub(crate) async fn set_room_visibility_route( match &body.visibility { room::Visibility::Public => { services().rooms.directory.set_public(&body.room_id)?; - info!( + t::info!( user_id = %sender_user, room_id = %body.room_id, "User made room public", @@ -269,7 +269,7 @@ pub(crate) async fn get_public_rooms_filtered_helper( } #[allow(clippy::too_many_lines)] -#[tracing::instrument] +#[t::instrument] fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result { let canonical_alias = services() .rooms @@ -292,7 +292,7 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result { .state_cache .room_joined_count(&room_id)? .unwrap_or_else(|| { - warn!("Room has no member count"); + t::warn!("Room has no member count"); 0 }) .try_into() @@ -306,7 +306,7 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result { serde_json::from_str(s.content.get()) .map(|c: RoomTopicEventContent| Some(c.topic)) .map_err(|_| { - error!("Invalid room topic event in database for room",); + t::error!("Invalid room topic event in database for room",); Error::bad_database("Invalid room topic event in database.") }) })?; @@ -371,7 +371,10 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result { _ => None, }) .map_err(|error| { - error!(%error, "Invalid room join rule event in database"); + t::error!( + %error, + "Invalid room join rule event in database" + ); Error::BadDatabase( "Invalid room join rule event in database.", ) diff --git a/src/api/client_server/keys.rs b/src/api/client_server/keys.rs index d2e3006f..cee61d50 100644 --- a/src/api/client_server/keys.rs +++ b/src/api/client_server/keys.rs @@ -21,10 +21,11 @@ use ruma::{ ServerName, UserId, }; use serde_json::json; -use tracing::debug; use super::SESSION_ID_LENGTH; -use crate::{services, utils, Ar, Error, Ra, Result}; +use crate::{ + observability::prelude::*, services, utils, Ar, Error, Ra, Result, +}; /// # `POST /_matrix/client/r0/keys/upload` /// @@ -465,7 +466,7 @@ async fn check_key_requests_back_off(server: &ServerName) -> Result<()> { if let Some(remaining) = min_elapsed_duration.checked_sub(time.elapsed()) { - debug!(%server, %tries, ?remaining, "Backing off from server"); + t::debug!(%server, %tries, ?remaining, "Backing off from server"); return Err(Error::BadServerResponse( "bad query, still backing off", )); @@ -504,7 +505,7 @@ async fn request_keys_from( match &result { Ok(_) => reset_key_request_back_off(server).await, Err(error) => { - debug!(%server, %error, "remote device key query failed"); + t::debug!(%server, %error, "remote device key query failed"); back_off_key_requests(server.to_owned()).await; } } diff --git a/src/api/client_server/media.rs b/src/api/client_server/media.rs index ca9dda86..3b8a04d6 100644 --- a/src/api/client_server/media.rs +++ b/src/api/client_server/media.rs @@ -17,9 +17,9 @@ use ruma::{ }, http_headers::{ContentDisposition, ContentDispositionType}, }; -use tracing::{debug, error, info, warn}; use crate::{ + observability::prelude::*, service::media::FileMeta, services, utils::{self, MxcData}, @@ -111,7 +111,11 @@ fn set_header_or_panic( header_value: HeaderValue, ) { if let Some(header_value) = response.headers().get(&header_name) { - error!(?header_name, ?header_value, "unexpected pre-existing header"); + t::error!( + ?header_name, + ?header_value, + "unexpected pre-existing header" + ); panic!( "expected {header_name:?} to be unset but it was set to \ {header_value:?}" @@ -203,12 +207,12 @@ struct RemoteResponse { /// Fetches remote media content from a URL specified in a /// `/_matrix/federation/v1/media/*/{mediaId}` `Location` header -#[tracing::instrument] +#[t::instrument] async fn get_redirected_content( location: String, ) -> Result { let location = location.parse().map_err(|error| { - warn!(location, %error, "Invalid redirect location"); + t::warn!(location, %error, "Invalid redirect location"); Error::BadServerResponse("Invalid redirect location") })?; let response = services() @@ -222,7 +226,7 @@ async fn get_redirected_content( .get(CONTENT_TYPE) .map(|value| { value.to_str().map_err(|error| { - error!( + t::error!( ?value, %error, "Invalid Content-Type header" @@ -238,7 +242,7 @@ async fn get_redirected_content( .get(CONTENT_DISPOSITION) .map(|value| { ContentDisposition::try_from(value.as_bytes()).map_err(|error| { - error!( + t::error!( ?value, %error, "Invalid Content-Disposition header" @@ -255,7 +259,7 @@ async fn get_redirected_content( }) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn get_remote_content_via_federation_api( mxc: &MxcData<'_>, ) -> Result { @@ -275,11 +279,11 @@ async fn get_remote_content_via_federation_api( let content = match content { authenticated_media_fed::FileOrLocation::File(content) => { - debug!("Got media from remote server"); + t::debug!("Got media from remote server"); content } authenticated_media_fed::FileOrLocation::Location(location) => { - debug!(location, "Following redirect"); + t::debug!(location, "Following redirect"); get_redirected_content(location).await? } }; @@ -291,7 +295,7 @@ async fn get_remote_content_via_federation_api( } #[allow(deprecated)] // unauthenticated media -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn get_remote_content_via_legacy_api( mxc: &MxcData<'_>, ) -> Result { @@ -319,7 +323,7 @@ async fn get_remote_content_via_legacy_api( }) } -#[tracing::instrument] +#[t::instrument] pub(crate) async fn get_remote_content( mxc: &MxcData<'_>, ) -> Result { @@ -327,7 +331,7 @@ pub(crate) async fn get_remote_content( let response = match fed_result { Ok(response) => { - debug!("Got remote content via authenticated media API"); + t::debug!("Got remote content via authenticated media API"); response } Err(Error::Federation(_, error)) @@ -335,7 +339,7 @@ pub(crate) async fn get_remote_content( // https://github.com/t2bot/matrix-media-repo/issues/609 || error.error_kind() == Some(&ErrorKind::Unauthorized) => { - info!( + t::info!( "Remote server does not support authenticated media, falling \ back to deprecated API" ); @@ -713,7 +717,7 @@ pub(crate) async fn get_content_thumbnail_route( }) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn get_remote_thumbnail_via_federation_api( server_name: &ruma::ServerName, request: authenticated_media_fed::get_content_thumbnail::v1::Request, @@ -728,11 +732,11 @@ async fn get_remote_thumbnail_via_federation_api( let content = match content { authenticated_media_fed::FileOrLocation::File(content) => { - debug!("Got thumbnail from remote server"); + t::debug!("Got thumbnail from remote server"); content } authenticated_media_fed::FileOrLocation::Location(location) => { - debug!(location, "Following redirect"); + t::debug!(location, "Following redirect"); get_redirected_content(location).await? } }; @@ -744,7 +748,7 @@ async fn get_remote_thumbnail_via_federation_api( } #[allow(deprecated)] // unauthenticated media -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn get_remote_thumbnail_via_legacy_api( server_name: &ruma::ServerName, authenticated_media_fed::get_content_thumbnail::v1::Request { @@ -784,7 +788,7 @@ async fn get_remote_thumbnail_via_legacy_api( }) } -#[tracing::instrument] +#[t::instrument] pub(crate) async fn get_remote_thumbnail( server_name: &ruma::ServerName, request: authenticated_media_fed::get_content_thumbnail::v1::Request, @@ -795,7 +799,7 @@ pub(crate) async fn get_remote_thumbnail( let response = match fed_result { Ok(response) => { - debug!("Got remote content via authenticated media API"); + t::debug!("Got remote content via authenticated media API"); response } Err(Error::Federation(_, error)) @@ -803,7 +807,7 @@ pub(crate) async fn get_remote_thumbnail( // https://github.com/t2bot/matrix-media-repo/issues/609 || error.error_kind() == Some(&ErrorKind::Unauthorized) => { - info!( + t::info!( "Remote server does not support authenticated media, falling \ back to deprecated API" ); @@ -891,7 +895,7 @@ async fn get_content_thumbnail_route_ruma( resp.content.content_type, )); } - Err(error) => warn!( + Err(error) => t::warn!( %error, "Failed to fetch thumbnail via federation, trying to fetch \ original media and create thumbnail ourselves" @@ -912,7 +916,9 @@ async fn get_content_thumbnail_route_ruma( return Ok(make_response(file, content_type)); } - error!("Source media doesn't exist even after fetching it from remote"); + t::error!( + "Source media doesn't exist even after fetching it from remote" + ); } Err(Error::BadRequest(ErrorKind::NotYetUploaded, "Media not found.")) diff --git a/src/api/client_server/membership.rs b/src/api/client_server/membership.rs index 7d6c9cdb..4d7c5cb6 100644 --- a/src/api/client_server/membership.rs +++ b/src/api/client_server/membership.rs @@ -31,10 +31,10 @@ use ruma::{ }; use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use tokio::sync::RwLock; -use tracing::{debug, error, info, warn}; use super::get_alias_helper; use crate::{ + observability::prelude::*, service::{ globals::SigningKeys, pdu::{gen_event_id_canonical_json, PduBuilder}, @@ -501,7 +501,7 @@ pub(crate) async fn joined_members_route( } #[allow(clippy::too_many_lines)] -#[tracing::instrument(skip(reason, _third_party_signed))] +#[t::instrument(skip(reason, _third_party_signed))] async fn join_room_by_id_helper( sender_user: Option<&UserId>, room_id: &RoomId, @@ -523,7 +523,7 @@ async fn join_room_by_id_helper( .state_cache .server_in_room(services().globals.server_name(), room_id)? { - info!("We can join locally"); + t::info!("We can join locally"); let join_rules_event = services().rooms.state_accessor.room_state_get( room_id, @@ -537,7 +537,7 @@ async fn join_room_by_id_helper( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()) .map_err(|error| { - warn!(%error, "Invalid join rules event"); + t::warn!(%error, "Invalid join rules event"); Error::bad_database( "Invalid join rules event in db.", ) @@ -636,7 +636,7 @@ async fn join_room_by_id_helper( return Err(error); } - info!( + t::info!( "We couldn't do the join locally, maybe federation can help to \ satisfy the restricted join requirements" ); @@ -791,12 +791,12 @@ async fn join_room_by_id_helper( ) .await?; } else { - info!("Joining over federation."); + t::info!("Joining over federation."); let (make_join_response, remote_server) = make_join_request(sender_user, room_id, servers).await?; - info!("make_join finished"); + t::info!("make_join finished"); let room_version_id = match make_join_response.room_version { Some(room_version) @@ -895,7 +895,7 @@ async fn join_room_by_id_helper( // It has enough fields to be called a proper event now let mut join_event = join_event_stub; - info!(server = %remote_server, "Asking other server for send_join"); + t::info!(server = %remote_server, "Asking other server for send_join"); let send_join_response = services() .sending .send_federation_request( @@ -911,10 +911,10 @@ async fn join_room_by_id_helper( ) .await?; - info!("send_join finished"); + t::info!("send_join finished"); if let Some(signed_raw) = &send_join_response.room_state.event { - info!( + t::info!( "There is a signed event. This room is probably using \ restricted joins. Adding signature to our event" ); @@ -956,7 +956,7 @@ async fn join_room_by_id_helper( .insert(remote_server.to_string(), signature.clone()); } Err(error) => { - warn!( + t::warn!( %error, server = %remote_server, event = ?signed_value, @@ -969,7 +969,7 @@ async fn join_room_by_id_helper( services().rooms.short.get_or_create_shortroomid(room_id)?; - info!("Parsing join event"); + t::info!("Parsing join event"); let parsed_join_pdu = PduEvent::from_id_val(event_id, join_event.clone()).map_err( |_| Error::BadServerResponse("Invalid join event PDU."), @@ -978,7 +978,7 @@ async fn join_room_by_id_helper( let mut state = HashMap::new(); let pub_key_map = RwLock::new(BTreeMap::new()); - info!("Fetching join signing keys"); + t::info!("Fetching join signing keys"); services() .rooms .event_handler @@ -989,7 +989,7 @@ async fn join_room_by_id_helper( ) .await?; - info!("Going through send_join response room_state"); + t::info!("Going through send_join response room_state"); for result in send_join_response.room_state.state.iter().map(|pdu| { validate_and_add_event_id(pdu, &room_version_id, &pub_key_map) }) { @@ -999,7 +999,7 @@ async fn join_room_by_id_helper( let pdu = PduEvent::from_id_val(&event_id, value.clone()).map_err( |error| { - warn!( + t::warn!( %error, object = ?value, "Invalid PDU in send_join response", @@ -1021,7 +1021,7 @@ async fn join_room_by_id_helper( } } - info!("Going through send_join response auth_chain"); + t::info!("Going through send_join response auth_chain"); for result in send_join_response.room_state.auth_chain.iter().map(|pdu| { validate_and_add_event_id(pdu, &room_version_id, &pub_key_map) @@ -1034,7 +1034,7 @@ async fn join_room_by_id_helper( services().rooms.outlier.add_pdu_outlier(&event_id, &value)?; } - info!("Running send_join auth check"); + t::info!("Running send_join auth check"); let authenticated = state_res::event_auth::auth_check( &state_res::RoomVersion::new(&room_version_id).map_err(|_| { Error::UnsupportedRoomVersion(room_version_id.clone()) @@ -1062,7 +1062,7 @@ async fn join_room_by_id_helper( }, ) .map_err(|error| { - warn!(%error, "Auth check failed"); + t::warn!(%error, "Auth check failed"); Error::BadRequest(ErrorKind::InvalidParam, "Auth check failed") })?; @@ -1073,7 +1073,7 @@ async fn join_room_by_id_helper( )); } - info!("Saving state from send_join"); + t::info!("Saving state from send_join"); let (statehash_before_join, new, removed) = services().rooms.state_compressor.save_state( room_id, @@ -1096,7 +1096,7 @@ async fn join_room_by_id_helper( .force_state(&room_token, statehash_before_join, new, removed) .await?; - info!("Updating joined counts for new room"); + t::info!("Updating joined counts for new room"); services().rooms.state_cache.update_joined_count(room_id)?; // We append to state before appending the pdu, so we don't have a @@ -1105,7 +1105,7 @@ async fn join_room_by_id_helper( let statehash_after_join = services().rooms.state.append_to_state(&parsed_join_pdu)?; - info!("Appending new room join event"); + t::info!("Appending new room join event"); services() .rooms .timeline @@ -1117,7 +1117,7 @@ async fn join_room_by_id_helper( ) .await?; - info!("Setting final room state for new room"); + t::info!("Setting final room state for new room"); // We set the room state after inserting the pdu, so that we never have // a moment in time where events in the current room state do // not exist @@ -1146,7 +1146,7 @@ async fn make_join_request( if remote_server == services().globals.server_name() { continue; } - info!(server = %remote_server, "Asking other server for make_join"); + t::info!(server = %remote_server, "Asking other server for make_join"); let make_join_response = services() .sending .send_federation_request( @@ -1164,7 +1164,7 @@ async fn make_join_request( return Ok((r, remote_server.clone())); } Err(error) => { - warn!( + t::warn!( %error, server = %remote_server, "Remote join request failed", @@ -1184,7 +1184,7 @@ async fn validate_and_add_event_id( ) -> Result<(OwnedEventId, CanonicalJsonObject)> { let mut value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - error!(%error, object = ?pdu, "Invalid PDU in server response"); + t::error!(%error, object = ?pdu, "Invalid PDU in server response"); Error::BadServerResponse("Invalid PDU in server response") })?; let event_id = EventId::parse(format!( @@ -1216,7 +1216,7 @@ async fn validate_and_add_event_id( } if time.elapsed() < min_elapsed_duration { - debug!(%event_id, "Backing off from event"); + t::debug!(%event_id, "Backing off from event"); return Err(Error::BadServerResponse( "bad event, still backing off", )); @@ -1224,7 +1224,7 @@ async fn validate_and_add_event_id( } let origin_server_ts = value.get("origin_server_ts").ok_or_else(|| { - error!("Invalid PDU, no origin_server_ts field"); + t::error!("Invalid PDU, no origin_server_ts field"); Error::BadRequest( ErrorKind::MissingParam, "Invalid PDU, no origin_server_ts field", @@ -1258,7 +1258,7 @@ async fn validate_and_add_event_id( if let Err(error) = ruma::signatures::verify_event(&keys, &value, room_version) { - warn!( + t::warn!( %event_id, %error, ?pdu, @@ -1361,7 +1361,7 @@ pub(crate) async fn invite_helper( }; if *pdu.event_id != *event_id { - warn!( + t::warn!( server = %user_id.server_name(), our_object = ?pdu_json, their_object = ?value, @@ -1481,14 +1481,14 @@ pub(crate) async fn leave_all_rooms(user_id: &UserId) -> Result<()> { }; if let Err(error) = leave_room(user_id, &room_id, None).await { - warn!(%user_id, %room_id, %error, "Failed to leave room"); + t::warn!(%user_id, %room_id, %error, "Failed to leave room"); } } Ok(()) } -#[tracing::instrument(skip(reason))] +#[t::instrument(skip(reason))] pub(crate) async fn leave_room( user_id: &UserId, room_id: &RoomId, @@ -1515,7 +1515,7 @@ pub(crate) async fn leave_room( // Fix for broken rooms let member_event = match member_event { None => { - error!("Trying to leave a room you are not a member of."); + t::error!("Trying to leave a room you are not a member of."); services().rooms.state_cache.update_membership( room_id, @@ -1557,7 +1557,7 @@ pub(crate) async fn leave_room( .await?; } else { if let Err(error) = remote_leave_room(user_id, room_id).await { - warn!(%error, "Failed to leave room remotely"); + t::warn!(%error, "Failed to leave room remotely"); // Don't tell the client about this error } diff --git a/src/api/client_server/profile.rs b/src/api/client_server/profile.rs index 8a84f743..3be9ab78 100644 --- a/src/api/client_server/profile.rs +++ b/src/api/client_server/profile.rs @@ -14,9 +14,11 @@ use ruma::{ }, }; use serde_json::value::to_raw_value; -use tracing::warn; -use crate::{service::pdu::PduBuilder, services, Ar, Error, Ra, Result}; +use crate::{ + observability::prelude::*, service::pdu::PduBuilder, services, Ar, Error, + Ra, Result, +}; /// # `PUT /_matrix/client/r0/profile/{userId}/displayname` /// @@ -91,7 +93,7 @@ pub(crate) async fn set_displayname_route( .build_and_append_pdu(pdu_builder, sender_user, &room_token) .await { - warn!(%error, "failed to add PDU"); + t::warn!(%error, "failed to add PDU"); } } @@ -203,7 +205,7 @@ pub(crate) async fn set_avatar_url_route( .build_and_append_pdu(pdu_builder, sender_user, &room_token) .await { - warn!(%error, "failed to add PDU"); + t::warn!(%error, "failed to add PDU"); }; } diff --git a/src/api/client_server/room.rs b/src/api/client_server/room.rs index ebb5a26b..93066238 100644 --- a/src/api/client_server/room.rs +++ b/src/api/client_server/room.rs @@ -27,11 +27,11 @@ use ruma::{ CanonicalJsonObject, OwnedRoomAliasId, RoomAliasId, RoomId, }; use serde_json::{json, value::to_raw_value}; -use tracing::{info, warn}; use crate::{ - api::client_server::invite_helper, service::pdu::PduBuilder, services, - utils::room_version::RoomVersion, Ar, Error, Ra, Result, + api::client_server::invite_helper, observability::prelude::*, + service::pdu::PduBuilder, services, utils::room_version::RoomVersion, Ar, + Error, Ra, Result, }; /// # `POST /_matrix/client/r0/createRoom` @@ -400,7 +400,7 @@ pub(crate) async fn create_room_route( for event in &body.initial_state { let mut pdu_builder = event.deserialize_as::().map_err(|error| { - warn!(%error, "Invalid initial state event"); + t::warn!(%error, "Invalid initial state event"); Error::BadRequest( ErrorKind::InvalidParam, "Invalid initial state event.", @@ -474,7 +474,7 @@ pub(crate) async fn create_room_route( invite_helper(sender_user, user_id, &room_id, None, body.is_direct) .await { - warn!(%error, "Invite helper failed"); + t::warn!(%error, "Invite helper failed"); }; } @@ -487,7 +487,7 @@ pub(crate) async fn create_room_route( services().rooms.directory.set_public(&room_id)?; } - info!(user_id = %sender_user, room_id = %room_id, "User created a room"); + t::info!(user_id = %sender_user, room_id = %room_id, "User created a room"); Ok(Ra(create_room::v3::Response::new(room_id))) } @@ -505,7 +505,7 @@ pub(crate) async fn get_room_event_route( let event = services().rooms.timeline.get_pdu(&body.event_id)?.ok_or_else( || { - warn!(event_id = %body.event_id, "Event not found"); + t::warn!(event_id = %body.event_id, "Event not found"); Error::BadRequest(ErrorKind::NotFound, "Event not found.") }, )?; diff --git a/src/api/client_server/session.rs b/src/api/client_server/session.rs index 228ab4d3..2e8560f9 100644 --- a/src/api/client_server/session.rs +++ b/src/api/client_server/session.rs @@ -13,10 +13,11 @@ use ruma::{ UserId, }; use serde::Deserialize; -use tracing::{info, warn}; use super::{DEVICE_ID_LENGTH, TOKEN_LENGTH}; -use crate::{services, utils, Ar, Error, Ra, Result}; +use crate::{ + observability::prelude::*, services, utils, Ar, Error, Ra, Result, +}; #[derive(Debug, Deserialize)] struct Claims { @@ -79,7 +80,7 @@ pub(crate) async fn login_route( } else if let Some(user) = user { UserId::parse(user) } else { - warn!(kind = ?body.login_info, "Bad login kind"); + t::warn!(kind = ?body.login_info, "Bad login kind"); return Err(Error::BadRequest( ErrorKind::forbidden(), "Bad login type.", @@ -184,7 +185,7 @@ pub(crate) async fn login_route( } else if let Some(user) = user { UserId::parse(user) } else { - warn!(kind = ?body.login_info, "Bad login kind"); + t::warn!(kind = ?body.login_info, "Bad login kind"); return Err(Error::BadRequest( ErrorKind::forbidden(), "Bad login type.", @@ -214,7 +215,10 @@ pub(crate) async fn login_route( user_id } _ => { - warn!(kind = ?body.login_info, "Unsupported or unknown login kind"); + t::warn!( + kind = ?body.login_info, + "Unsupported or unknown login kind" + ); return Err(Error::BadRequest( ErrorKind::Unknown, "Unsupported login type.", @@ -250,7 +254,7 @@ pub(crate) async fn login_route( )?; } - info!(%user_id, %device_id, "User logged in"); + t::info!(%user_id, %device_id, "User logged in"); // Homeservers are still required to send the `home_server` field #[allow(deprecated)] @@ -292,7 +296,11 @@ pub(crate) async fn logout_route( services().users.remove_device(sender_user, sender_device)?; - info!(user_id = %sender_user, device_id = %sender_device, "User logged out"); + t::info!( + user_id = %sender_user, + device_id = %sender_device, + "User logged out" + ); Ok(Ra(logout::v3::Response::new())) } diff --git a/src/api/client_server/state.rs b/src/api/client_server/state.rs index 2e6f3b13..79b30d80 100644 --- a/src/api/client_server/state.rs +++ b/src/api/client_server/state.rs @@ -13,9 +13,11 @@ use ruma::{ EventId, RoomAliasId, RoomId, UserId, }; use serde::Deserialize; -use tracing::warn; -use crate::{service::pdu::PduBuilder, services, Ar, Error, Ra, Result}; +use crate::{ + observability::prelude::*, service::pdu::PduBuilder, services, Ar, Error, + Ra, Result, +}; /// # `PUT /_matrix/client/r0/rooms/{roomId}/state/{eventType}/{stateKey}` /// @@ -146,9 +148,10 @@ pub(crate) async fn get_state_events_for_key_route( .state_accessor .room_state_get(&body.room_id, &body.event_type, &body.state_key)? .ok_or_else(|| { - warn!( + t::warn!( "State event {:?} not found in room {:?}", - &body.event_type, &body.room_id + &body.event_type, + &body.room_id ); Error::BadRequest(ErrorKind::NotFound, "State event not found.") })?; @@ -187,9 +190,10 @@ pub(crate) async fn get_state_events_for_empty_key_route( .state_accessor .room_state_get(&body.room_id, &body.event_type, "")? .ok_or_else(|| { - warn!( + t::warn!( "State event {:?} not found in room {:?}", - &body.event_type, &body.room_id + &body.event_type, + &body.room_id ); Error::BadRequest(ErrorKind::NotFound, "State event not found.") })?; @@ -278,7 +282,7 @@ async fn validate_canonical_alias_event( .and_then(|old_event| { serde_json::from_str::(old_event.content.get()) .inspect_err(|error| { - warn!( + t::warn!( %error, event_id=%old_event.event_id, "Invalid canonical alias event in database" diff --git a/src/api/client_server/sync.rs b/src/api/client_server/sync.rs index 2a17aa17..200bcf15 100644 --- a/src/api/client_server/sync.rs +++ b/src/api/client_server/sync.rs @@ -1,8 +1,8 @@ use ruma::{events::StateEventType, RoomId, UserId}; -use tracing::error; use crate::{ - service::rooms::timeline::PduCount, services, Error, PduEvent, Result, + observability::prelude::*, service::rooms::timeline::PduCount, services, + Error, PduEvent, Result, }; pub(crate) mod msc3575; @@ -26,7 +26,7 @@ fn load_timeline( .filter_map(|x| match x { Ok(x) => Some(x), Err(error) => { - error!(%error, "Bad PDU in pdus_since"); + t::error!(%error, "Bad PDU in pdus_since"); None } }) diff --git a/src/api/client_server/sync/msc3575.rs b/src/api/client_server/sync/msc3575.rs index 1de1c7d1..5a0b6765 100644 --- a/src/api/client_server/sync/msc3575.rs +++ b/src/api/client_server/sync/msc3575.rs @@ -21,11 +21,11 @@ use ruma::{ }, uint, JsOption, UInt, UserId, }; -use tracing::{debug, error}; use super::{load_timeline, share_encrypted_room}; use crate::{ - service::rooms::timeline::PduCount, services, Ar, Error, Ra, Result, + observability::prelude::*, service::rooms::timeline::PduCount, services, + Ar, Error, Ra, Result, }; #[allow(clippy::too_many_lines)] @@ -93,7 +93,7 @@ pub(crate) async fn sync_events_v4_route( let Some(current_shortstatehash) = services().rooms.state.get_room_shortstatehash(room_id)? else { - error!(%room_id, "Room has no state"); + t::error!(%room_id, "Room has no state"); continue; }; @@ -171,7 +171,10 @@ pub(crate) async fn sync_events_v4_route( let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!( + %event_id, + "Event in state not found" + ); continue; }; if pdu.kind == TimelineEventType::RoomMember { @@ -450,7 +453,7 @@ pub(crate) async fn sync_events_v4_route( .map_or(Ok::<_, Error>(None), |(pdu_count, _)| { Ok(Some(match pdu_count { PduCount::Backfilled(_) => { - error!("Timeline in backfill state?!"); + t::error!("Timeline in backfill state?!"); "0".to_owned() } PduCount::Normal(c) => c.to_string(), @@ -602,7 +605,7 @@ pub(crate) async fn sync_events_v4_route( } match tokio::time::timeout(duration, watcher).await { Ok(x) => x.expect("watcher should succeed"), - Err(error) => debug!(%error, "Timed out"), + Err(error) => t::debug!(%error, "Timed out"), }; } diff --git a/src/api/client_server/sync/v3.rs b/src/api/client_server/sync/v3.rs index 65830053..aa111608 100644 --- a/src/api/client_server/sync/v3.rs +++ b/src/api/client_server/sync/v3.rs @@ -23,10 +23,10 @@ use ruma::{ }, uint, DeviceId, EventId, OwnedRoomId, OwnedUserId, RoomId, UInt, UserId, }; -use tracing::{debug, error, field}; use super::{load_timeline, share_encrypted_room}; use crate::{ + observability::prelude::*, service::{pdu::EventHash, rooms::timeline::PduCount}, services, utils, Ar, Error, PduEvent, Ra, Result, }; @@ -85,7 +85,7 @@ struct SyncContext<'a> { /// - If the user left after `since`: `prev_batch` token, empty state (TODO: /// subset of the state at the point of the leave) #[allow(clippy::too_many_lines)] -#[tracing::instrument( +#[t::instrument( skip_all, fields( sender_user, @@ -99,12 +99,12 @@ struct SyncContext<'a> { pub(crate) async fn sync_events_route( body: Ar, ) -> Result, Ra> { - let current_span = tracing::Span::current(); + let current_span = t::Span::current(); let sender_user = body.sender_user.expect("user is authenticated"); - current_span.record("sender_user", field::display(&sender_user)); + current_span.record("sender_user", t::field::display(&sender_user)); let sender_device = body.sender_device.expect("user is authenticated"); - current_span.record("sender_device", field::display(&sender_device)); + current_span.record("sender_device", t::field::display(&sender_device)); let body = body.body; // Setup watchers, so if there's no response, we can wait for them @@ -279,13 +279,13 @@ pub(crate) async fn sync_events_route( } match tokio::time::timeout(duration, watcher).await { Ok(x) => x.expect("watcher should succeed"), - Err(error) => debug!(%error, "Timed out"), + Err(error) => t::debug!(%error, "Timed out"), }; } Ok(Ra(response)) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn collect_joined_rooms( ctx: &SyncContext<'_>, device_list_updates: &mut HashSet, @@ -316,7 +316,7 @@ async fn collect_joined_rooms( Ok(joined_rooms) } -#[tracing::instrument(skip_all, fields(room_id = %room_id))] +#[t::instrument(skip_all, fields(room_id = %room_id))] #[allow(clippy::too_many_arguments, clippy::too_many_lines)] async fn load_joined_room( ctx: &SyncContext<'_>, @@ -366,7 +366,7 @@ async fn load_joined_room( let Some(current_shortstatehash) = services().rooms.state.get_room_shortstatehash(room_id)? else { - error!("Room has no state"); + t::error!("Room has no state"); return Err(Error::BadDatabase("Room has no state")); }; @@ -526,7 +526,7 @@ async fn load_joined_room( let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; state_events.push(pdu); @@ -544,7 +544,7 @@ async fn load_joined_room( let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; @@ -615,7 +615,7 @@ async fn load_joined_room( let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; @@ -748,7 +748,7 @@ async fn load_joined_room( lazy_loaded.insert(state_key_userid); } Err(error) => { - error!( + t::error!( event_id = %pdu.event_id, %error, "Invalid state key for member event", @@ -834,7 +834,7 @@ async fn load_joined_room( |(pdu_count, _)| { Ok(Some(match pdu_count { PduCount::Backfilled(_) => { - error!("Timeline in backfill state?!"); + t::error!("Timeline in backfill state?!"); "0".to_owned() } PduCount::Normal(c) => c.to_string(), @@ -921,7 +921,7 @@ async fn load_joined_room( }) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn collect_left_rooms( ctx: &SyncContext<'_>, ) -> Result> { @@ -1017,7 +1017,7 @@ async fn collect_left_rooms( ctx.sender_user.as_str(), )? else { - error!("Left room but no left state event"); + t::error!("Left room but no left state event"); continue; }; @@ -1026,7 +1026,7 @@ async fn collect_left_rooms( .state_accessor .pdu_shortstatehash(&left_event_id)? else { - error!("Leave event has no state"); + t::error!("Leave event has no state"); continue; }; @@ -1059,7 +1059,7 @@ async fn collect_left_rooms( let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? else { - error!(%event_id, "Event in state not found"); + t::error!(%event_id, "Event in state not found"); continue; }; @@ -1094,7 +1094,7 @@ async fn collect_left_rooms( Ok(left_rooms) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn collect_invited_rooms( ctx: &SyncContext<'_>, ) -> Result> { diff --git a/src/api/ruma_wrapper/axum.rs b/src/api/ruma_wrapper/axum.rs index 712386d9..2084567b 100644 --- a/src/api/ruma_wrapper/axum.rs +++ b/src/api/ruma_wrapper/axum.rs @@ -25,10 +25,12 @@ use ruma::{ OwnedServerName, OwnedUserId, UserId, }; use serde::Deserialize; -use tracing::{error, warn}; use super::{Ar, Ra}; -use crate::{service::appservice::RegistrationInfo, services, Error, Result}; +use crate::{ + observability::prelude::*, service::appservice::RegistrationInfo, services, + Error, Result, +}; enum Token { Appservice(Box), @@ -82,7 +84,7 @@ async fn ar_from_request_inner( let query_params: QueryParams = match serde_html_form::from_str(query) { Ok(params) => params, Err(error) => { - error!(%error, %query, "Failed to deserialize query parameters"); + t::error!(%error, %query, "Failed to deserialize query parameters"); return Err(Error::BadRequest( ErrorKind::Unknown, "Failed to read query parameters", @@ -182,7 +184,10 @@ async fn ar_from_request_inner( .extract::>>() .await .map_err(|error| { - warn!(%error, "Missing or invalid Authorization header"); + t::warn!( + %error, + "Missing or invalid Authorization header" + ); let msg = match error.reason() { TypedHeaderRejectionReason::Missing => { @@ -199,7 +204,7 @@ async fn ar_from_request_inner( if let Some(destination) = x_matrix.destination { if destination != services().globals.server_name() { - warn!( + t::warn!( %destination, "Incorrect destination in X-Matrix header" ); @@ -278,7 +283,7 @@ async fn ar_from_request_inner( let keys = match keys_result { Ok(b) => b, Err(error) => { - warn!(%error, "Failed to fetch signing keys"); + t::warn!(%error, "Failed to fetch signing keys"); return Err(Error::BadRequest( ErrorKind::forbidden(), "Failed to fetch signing keys.", @@ -304,7 +309,7 @@ async fn ar_from_request_inner( { Ok(()) => (None, None, Some(x_matrix.origin), None), Err(error) => { - warn!( + t::warn!( %error, origin = %x_matrix.origin, object = ?request_map, @@ -312,7 +317,7 @@ async fn ar_from_request_inner( ); if parts.uri.to_string().contains('@') { - warn!( + t::warn!( "Request uri contained '@' character. Make \ sure your reverse proxy gives Grapevine the \ raw uri (apache: use nocanon)" @@ -405,7 +410,7 @@ where { type Rejection = Error; - #[tracing::instrument("ar_from_request", skip_all)] + #[t::instrument("ar_from_request", skip_all)] async fn from_request( req: axum::extract::Request, _state: &S, @@ -415,7 +420,7 @@ where let body = T::try_from_http_request(pieces.http_request, &pieces.path_params) .map_err(|error| { - warn!( + t::warn!( %error, body = ?pieces.json_body, "Request body JSON structure is incorrect" diff --git a/src/api/server_server.rs b/src/api/server_server.rs index 9c29b60b..6d718c90 100644 --- a/src/api/server_server.rs +++ b/src/api/server_server.rs @@ -63,12 +63,11 @@ use ruma::{ }; use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use tokio::sync::RwLock; -use tracing::{debug, error, field, trace, trace_span, warn}; use super::appservice_server; use crate::{ api::client_server::{self, claim_keys_helper, get_keys_helper}, - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, service::{ globals::SigningKeys, pdu::{gen_event_id_canonical_json, PduBuilder}, @@ -147,7 +146,7 @@ pub(crate) enum AllowLoopbackRequests { No, } -#[tracing::instrument(skip(request, log_error, allow_loopback), fields(url))] +#[t::instrument(skip(request, log_error, allow_loopback), fields(url))] pub(crate) async fn send_request( destination: &ServerName, request: T, @@ -169,7 +168,7 @@ where )); } - debug!("Preparing to send request"); + t::debug!("Preparing to send request"); let mut write_destination_to_cache = false; @@ -201,7 +200,7 @@ where &[MatrixVersion::V1_11], ) .map_err(|error| { - warn!( + t::warn!( %error, actual_destination = actual_destination_str, "Failed to find destination", @@ -273,8 +272,8 @@ where // can be enabled selectively using `filter = // grapevine[outgoing_request_curl]=trace` in config - trace_span!("outgoing_request_curl").in_scope(|| { - trace!( + t::trace_span!("outgoing_request_curl").in_scope(|| { + t::trace!( cmd = utils::curlify(&http_request), "curl command line for outgoing request" ); @@ -282,21 +281,21 @@ where let reqwest_request = reqwest::Request::try_from(http_request)?; let url = reqwest_request.url().clone(); - tracing::Span::current().record("url", field::display(url)); + t::Span::current().record("url", t::field::display(url)); - debug!("Sending request"); + t::debug!("Sending request"); let response = services().globals.federation_client().execute(reqwest_request).await; let mut response = response.inspect_err(|error| { if log_error == LogRequestError::Yes { - warn!(%error, "Could not send request"); + t::warn!(%error, "Could not send request"); } })?; // reqwest::Response -> http::Response conversion let status = response.status(); - debug!(status = u16::from(status), "Received response"); + t::debug!(status = u16::from(status), "Received response"); let mut http_response_builder = http::Response::builder().status(status).version(response.version()); mem::swap( @@ -306,16 +305,16 @@ where .expect("http::response::Builder is usable"), ); - debug!("Getting response bytes"); + t::debug!("Getting response bytes"); // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - warn!(%error, "Server error"); + t::warn!(%error, "Server error"); Vec::new().into() }); - debug!("Got response bytes"); + t::debug!("Got response bytes"); if status != 200 { - warn!( + t::warn!( status = u16::from(status), response = dbg_truncate_str(String::from_utf8_lossy(&body).as_ref(), 100) @@ -335,7 +334,7 @@ where )); } - debug!("Parsing response bytes"); + t::debug!("Parsing response bytes"); let response = T::IncomingResponse::try_from_http_response(http_response); if response.is_ok() && write_destination_to_cache { METRICS.record_lookup(Lookup::FederationDestination, FoundIn::Remote); @@ -346,7 +345,7 @@ where } response.map_err(|e| { - warn!(error = %e, "Invalid 200 response"); + t::warn!(error = %e, "Invalid 200 response"); Error::BadServerResponse("Server returned bad 200 response.") }) } @@ -374,29 +373,29 @@ fn add_port_to_hostname(destination_str: &str) -> FedDest { /// Numbers in comments below refer to bullet points in linked section of /// specification #[allow(clippy::too_many_lines)] -#[tracing::instrument(ret(level = "debug"))] +#[t::instrument(ret(level = "debug"))] async fn find_actual_destination( destination: &'_ ServerName, ) -> (FedDest, FedDest) { - debug!("Finding actual destination"); + t::debug!("Finding actual 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) { Some(host_port) => { - debug!("1: IP literal with provided or default port"); + t::debug!("1: IP literal with provided or default port"); host_port } None => { if let Some(pos) = destination_str.find(':') { - debug!("2: Hostname with included port"); + t::debug!("2: Hostname with included port"); let (host, port) = destination_str.split_at(pos); FedDest::Named(host.to_owned(), port.to_owned()) } else { - debug!(%destination, "Requesting well known"); + t::debug!(%destination, "Requesting well known"); if let Some(delegated_hostname) = request_well_known(destination.as_str()).await { - debug!("3: A .well-known file is available"); + t::debug!("3: A .well-known file is available"); hostname = add_port_to_hostname(&delegated_hostname) .to_uri_string(); if let Some(host_and_port) = @@ -404,15 +403,19 @@ async fn find_actual_destination( { host_and_port } else if let Some(pos) = delegated_hostname.find(':') { - debug!("3.2: Hostname with port in .well-known file"); + t::debug!( + "3.2: Hostname with port in .well-known file" + ); let (host, port) = delegated_hostname.split_at(pos); FedDest::Named(host.to_owned(), port.to_owned()) } else { - debug!("Delegated hostname has no port in this branch"); + t::debug!( + "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"); + t::debug!("3.3: SRV lookup successful"); let force_port = hostname_override.port(); if let Ok(override_ip) = services() @@ -434,7 +437,7 @@ async fn find_actual_destination( ), ); } else { - warn!( + t::warn!( "Using SRV record, but could not resolve \ to IP" ); @@ -449,7 +452,7 @@ async fn find_actual_destination( add_port_to_hostname(&delegated_hostname) } } else { - debug!( + t::debug!( "3.4: No SRV records, just use the hostname \ from .well-known" ); @@ -457,11 +460,11 @@ async fn find_actual_destination( } } } else { - debug!("4: No .well-known or an error occured"); + t::debug!("4: No .well-known or an error occured"); if let Some(hostname_override) = query_srv_record(&destination_str).await { - debug!("4: SRV record found"); + t::debug!("4: SRV record found"); let force_port = hostname_override.port(); if let Ok(override_ip) = services() @@ -483,7 +486,7 @@ async fn find_actual_destination( ), ); } else { - warn!( + t::warn!( "Using SRV record, but could not resolve to IP" ); } @@ -494,14 +497,14 @@ async fn find_actual_destination( add_port_to_hostname(&hostname) } } else { - debug!("5: No SRV record found"); + t::debug!("5: No SRV record found"); add_port_to_hostname(&destination_str) } } } } }; - debug!(?actual_destination, "Resolved actual destination"); + t::debug!(?actual_destination, "Resolved actual destination"); // Can't use get_ip_with_port here because we don't want to add a port // to an IP address if it wasn't specified @@ -518,7 +521,7 @@ async fn find_actual_destination( (actual_destination, hostname) } -#[tracing::instrument(ret(level = "debug"))] +#[t::instrument(ret(level = "debug"))] async fn query_given_srv_record(record: &str) -> Option { services() .globals @@ -540,7 +543,7 @@ async fn query_given_srv_record(record: &str) -> Option { .unwrap_or(None) } -#[tracing::instrument(ret(level = "debug"))] +#[t::instrument(ret(level = "debug"))] async fn query_srv_record(hostname: &'_ str) -> Option { let hostname = hostname.trim_end_matches('.'); @@ -553,7 +556,7 @@ async fn query_srv_record(hostname: &'_ str) -> Option { } } -#[tracing::instrument(ret(level = "debug"))] +#[t::instrument(ret(level = "debug"))] async fn request_well_known(destination: &str) -> Option { let response = services() .globals @@ -561,13 +564,13 @@ async fn request_well_known(destination: &str) -> Option { .get(format!("https://{destination}/.well-known/matrix/server")) .send() .await; - debug!("Got well known response"); + t::debug!("Got well known response"); if let Err(error) = &response { - debug!(%error, "Failed to request .well-known"); + t::debug!(%error, "Failed to request .well-known"); return None; } let text = response.ok()?.text().await; - debug!("Got well known response text"); + t::debug!("Got well known response text"); let body: serde_json::Value = serde_json::from_str(&text.ok()?).ok()?; Some(body.get("m.server")?.as_str()?.to_owned()) } @@ -695,13 +698,13 @@ pub(crate) async fn get_public_rooms_route( })) } -#[tracing::instrument(skip(pdu))] +#[t::instrument(skip(pdu))] pub(crate) fn parse_incoming_pdu( pdu: &RawJsonValue, ) -> Result<(OwnedEventId, CanonicalJsonObject, OwnedRoomId)> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()).map_err(|error| { - warn!(%error, object = ?pdu, "Error parsing incoming event"); + t::warn!(%error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; @@ -747,7 +750,7 @@ pub(crate) async fn send_transaction_message_route( for pdu in &body.pdus { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - warn!(%error, object = ?pdu, "Error parsing incoming event"); + t::warn!(%error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; let room_id: OwnedRoomId = value @@ -764,7 +767,7 @@ pub(crate) async fn send_transaction_message_route( .get_create_content::(&room_id) .is_err() { - debug!(%room_id, "This server is not in the room"); + t::debug!(%room_id, "This server is not in the room"); continue; } @@ -772,7 +775,7 @@ pub(crate) async fn send_transaction_message_route( let (event_id, value, room_id) = match r { Ok(t) => t, Err(error) => { - warn!(%error, object = ?pdu, "Error parsing incoming event"); + t::warn!(%error, object = ?pdu, "Error parsing incoming event"); continue; } }; @@ -803,7 +806,7 @@ pub(crate) async fn send_transaction_message_route( ); drop(federation_token); - debug!( + t::debug!( %event_id, elapsed = ?start_time.elapsed(), "Finished handling event", @@ -813,7 +816,7 @@ pub(crate) async fn send_transaction_message_route( for pdu in &resolved_map { if let (event_id, Err(error)) = pdu { if matches!(error, Error::BadRequest(ErrorKind::NotFound, _)) { - warn!(%error, %event_id, "Incoming PDU failed"); + t::warn!(%error, %event_id, "Incoming PDU failed"); } } } @@ -828,7 +831,7 @@ pub(crate) async fn send_transaction_message_route( for (room_id, room_updates) in receipt.receipts { for (user_id, user_updates) in room_updates.read { if user_id.server_name() != sender_servername { - warn!( + t::warn!( %user_id, %sender_servername, "Got receipt EDU from incorrect homeserver, \ @@ -874,7 +877,7 @@ pub(crate) async fn send_transaction_message_route( )?; } else { // TODO fetch missing events - debug!( + t::debug!( ?user_updates, "No known event ids in read receipt", ); @@ -884,7 +887,7 @@ pub(crate) async fn send_transaction_message_route( } Edu::Typing(typing) => { if typing.user_id.server_name() != sender_servername { - warn!( + t::warn!( user_id = %typing.user_id, %sender_servername, "Got typing EDU from incorrect homeserver, ignoring", @@ -922,7 +925,7 @@ pub(crate) async fn send_transaction_message_route( .. }) => { if user_id.server_name() != sender_servername { - warn!( + t::warn!( %user_id, %sender_servername, "Got device list update EDU from incorrect homeserver, \ @@ -939,7 +942,7 @@ pub(crate) async fn send_transaction_message_route( messages, }) => { if sender.server_name() != sender_servername { - warn!( + t::warn!( user_id = %sender, %sender_servername, "Got direct-to-device EDU from incorrect homeserver, \ @@ -965,7 +968,7 @@ pub(crate) async fn send_transaction_message_route( &ev_type.to_string(), event.deserialize_as().map_err( |error| { - warn!( + t::warn!( %error, object = ?event.json(), "To-Device event is invalid", @@ -1018,7 +1021,7 @@ pub(crate) async fn send_transaction_message_route( self_signing_key, }) => { if user_id.server_name() != sender_servername { - warn!( + t::warn!( %user_id, %sender_servername, "Got signing key update from incorrect homeserver, \ @@ -1063,7 +1066,7 @@ pub(crate) async fn get_event_route( let event = services().rooms.timeline.get_pdu_json(&body.event_id)?.ok_or_else( || { - warn!(event_id = %body.event_id, "Event not found"); + t::warn!(event_id = %body.event_id, "Event not found"); Error::BadRequest(ErrorKind::NotFound, "Event not found.") }, )?; @@ -1116,7 +1119,7 @@ pub(crate) async fn get_backfill_route( let sender_servername = body.sender_servername.as_ref().expect("server is authenticated"); - debug!(server = %sender_servername, "Got backfill request"); + t::debug!(server = %sender_servername, "Got backfill request"); if !services() .rooms @@ -1225,7 +1228,7 @@ pub(crate) async fn get_missing_events_route( })?; if event_room_id != body.room_id { - warn!( + t::warn!( event_id = %queued_events[i], expected_room_id = %body.room_id, actual_room_id = %event_room_id, @@ -1308,7 +1311,7 @@ pub(crate) async fn get_event_authorization_route( let event = services().rooms.timeline.get_pdu_json(&body.event_id)?.ok_or_else( || { - warn!(event_id = %body.event_id, "Event not found"); + t::warn!(event_id = %body.event_id, "Event not found"); Error::BadRequest(ErrorKind::NotFound, "Event not found.") }, )?; @@ -1399,7 +1402,7 @@ pub(crate) async fn get_room_state_route( { Some(PduEvent::convert_to_outgoing_federation_event(json)) } else { - error!(%event_id, "Could not find event JSON for event"); + t::error!(%event_id, "Could not find event JSON for event"); None } }) @@ -1504,7 +1507,7 @@ pub(crate) async fn create_join_event_template_route( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()).map_err( |error| { - warn!(%error, "Invalid join rules event"); + t::warn!(%error, "Invalid join rules event"); Error::bad_database("Invalid join rules event in db.") }, ) @@ -1601,7 +1604,7 @@ async fn create_join_event( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()).map_err( |error| { - warn!(%error, "Invalid join rules event"); + t::warn!(%error, "Invalid join rules event"); Error::bad_database("Invalid join rules event in db.") }, ) @@ -1864,7 +1867,7 @@ pub(crate) async fn create_invite_route( let pdu: PduEvent = serde_json::from_value(event.into()).map_err(|error| { - warn!(%error, "Invalid invite event"); + t::warn!(%error, "Invalid invite event"); Error::BadRequest(ErrorKind::InvalidParam, "Invalid invite event.") })?; @@ -2099,7 +2102,7 @@ pub(crate) async fn media_download_route( let content_disposition = content_disposition.and_then(|s| { s.parse().inspect_err( - |error| warn!(%error, "Invalid Content-Disposition in database"), + |error| t::warn!(%error, "Invalid Content-Disposition in database"), ) .ok() }); diff --git a/src/cli/check_config.rs b/src/cli/check_config.rs index 943491bb..b8501d91 100644 --- a/src/cli/check_config.rs +++ b/src/cli/check_config.rs @@ -1,12 +1,10 @@ -use tracing::info; - -use crate::{cli::CheckConfigArgs, config, error}; +use crate::{cli::CheckConfigArgs, config, error, observability::prelude::*}; pub(crate) async fn run( args: CheckConfigArgs, ) -> Result<(), error::CheckConfigCommand> { let _config = config::load(args.config.config.as_ref(), args.sandboxed).await?; - info!("Configuration looks good"); + t::info!("Configuration looks good"); Ok(()) } diff --git a/src/cli/serve.rs b/src/cli/serve.rs index d08807b6..2d963e21 100644 --- a/src/cli/serve.rs +++ b/src/cli/serve.rs @@ -46,7 +46,6 @@ use tower_http::{ trace::TraceLayer, ServiceBuilderExt as _, }; -use tracing::{debug, info, info_span, warn, Instrument}; use super::ServeArgs; use crate::{ @@ -58,7 +57,9 @@ use crate::{ }, config::{self, Config, ListenComponent, ListenConfig, ListenTransport}, database::KeyValueDatabase, - error, observability, services, set_application_state, + error, observability, + observability::prelude::*, + services, set_application_state, utils::{ self, error::{Error, Result}, @@ -78,7 +79,7 @@ pub(crate) async fn run(args: ServeArgs) -> Result<(), error::ServeCommand> { let (_guard, reload_handles) = observability::init(&config)?; - info!("Loading database"); + t::info!("Loading database"); let db = Box::leak(Box::new( KeyValueDatabase::load_or_create(&config) .map_err(Error::DatabaseError)?, @@ -92,19 +93,19 @@ pub(crate) async fn run(args: ServeArgs) -> Result<(), error::ServeCommand> { db.apply_migrations().await.map_err(Error::DatabaseError)?; - info!("Starting background tasks"); + t::info!("Starting background tasks"); services().admin.start_handler(); services().sending.start_handler(); KeyValueDatabase::start_cleanup_task(); services().globals.set_emergency_access(); - info!("Starting server"); + t::info!("Starting server"); run_server().await?; Ok(()) } -#[tracing::instrument] +#[t::instrument] async fn federation_self_test() -> Result<()> { let response = server_server::send_request( &services().globals.config.server_name, @@ -119,7 +120,7 @@ async fn federation_self_test() -> Result<()> { .as_ref() .is_none_or(|s| s.name.as_deref() != Some(env!("CARGO_PKG_NAME"))) { - error!(?response, "unexpected server version"); + t::error!(?response, "unexpected server version"); return Err(Error::BadConfig( "Got unexpected version from our own version endpoint", )); @@ -309,7 +310,7 @@ async fn run_server() -> Result<(), error::Serve> { |h| h.proxied_address().map(|addr| addr.source), ); - tracing::info_span!( + t::info_span!( "http_request", otel.name = format!("{method} {endpoint}"), %method, @@ -320,21 +321,17 @@ async fn run_server() -> Result<(), error::Serve> { ), ) }) - .on_request( - |request: &http::Request<_>, _span: &tracing::Span| { - // can be enabled selectively using `filter = - // grapevine[incoming_request_curl]=trace` in config - tracing::trace_span!("incoming_request_curl").in_scope( - || { - tracing::trace!( - cmd = utils::curlify(request), - "curl command line for incoming request \ - (guessed hostname)" - ); - }, + .on_request(|request: &http::Request<_>, _span: &t::Span| { + // can be enabled selectively using `filter = + // grapevine[incoming_request_curl]=trace` in config + t::trace_span!("incoming_request_curl").in_scope(|| { + t::trace!( + cmd = utils::curlify(request), + "curl command line for incoming request (guessed \ + hostname)" ); - }, - ), + }); + }), ) .layer(axum::middleware::from_fn(unrecognized_method)) .layer( @@ -372,7 +369,7 @@ async fn run_server() -> Result<(), error::Serve> { } for listen in &config.listen { - info!(listener = %listen, "Listening for incoming traffic"); + t::info!(listener = %listen, "Listening for incoming traffic"); spawner.spawn_server(listen.clone())?; } @@ -382,7 +379,7 @@ async fn run_server() -> Result<(), error::Serve> { federation_self_test() .await .map_err(error::Serve::FederationSelfTestFailed)?; - debug!("Federation self-test completed successfully"); + t::debug!("Federation self-test completed successfully"); } set_application_state(ApplicationState::Ready); @@ -420,7 +417,7 @@ async fn unrecognized_method( let uri = req.uri().clone(); let inner = next.run(req).await; if inner.status() == StatusCode::METHOD_NOT_ALLOWED { - warn!(%method, %uri, "Method not allowed"); + t::warn!(%method, %uri, "Method not allowed"); return Ok(Ra(UiaaResponse::MatrixError(RumaError { body: ErrorBody::Standard { kind: ErrorKind::Unrecognized, @@ -747,13 +744,13 @@ async fn handle_signals( let sig = loop { tokio::select! { () = sighup() => { - info!("Received reload request"); + t::info!("Received reload request"); set_application_state(ApplicationState::Reloading); if let Some(tls_config) = tls_config.as_ref() { if let Err(error) = reload_tls_config(tls_config).await { - error!(?error, "Failed to reload TLS config"); + t::error!(?error, "Failed to reload TLS config"); } } @@ -764,7 +761,7 @@ async fn handle_signals( } }; - warn!(signal = %sig, "Shutting down due to signal"); + t::warn!(signal = %sig, "Shutting down due to signal"); services().globals.shutdown(); @@ -787,7 +784,7 @@ async fn unauthenticated_media_disabled(_: Uri) -> impl IntoResponse { } async fn not_found(method: Method, uri: Uri) -> impl IntoResponse { - debug!(%method, %uri, "Unknown route"); + t::debug!(%method, %uri, "Unknown route"); Error::BadRequest(ErrorKind::Unrecognized, "Unrecognized request") } @@ -853,7 +850,7 @@ macro_rules! impl_ruma_handler { on( method_filter, |$( $ty: $ty, )* req: Ar| async move { - let span = info_span!( + let span = t::info_span!( "run_ruma_handler", auth.user = ?req.sender_user, auth.device = ?req.sender_device, diff --git a/src/database.rs b/src/database.rs index f7cb1352..caa56022 100644 --- a/src/database.rs +++ b/src/database.rs @@ -11,10 +11,10 @@ use ruma::{ push::Ruleset, EventId, OwnedRoomId, RoomId, UserId, }; -use tracing::{debug, error, info, info_span, warn, Instrument}; use crate::{ config::DatabaseBackend, + observability::prelude::*, service::{ media::MediaFileKey, rooms::{ @@ -258,7 +258,7 @@ impl KeyValueDatabase { } if count > 1 { - warn!("Multiple databases at database_path detected"); + t::warn!("Multiple databases at database_path detected"); return Ok(()); } @@ -469,7 +469,7 @@ impl KeyValueDatabase { let room_id = parts.next().expect("split always returns one element"); let Some(servername) = parts.next() else { - error!("Migration: Invalid roomserverid in db."); + t::error!("Migration: Invalid roomserverid in db."); continue; }; let mut serverroomid = servername.to_vec(); @@ -532,7 +532,7 @@ impl KeyValueDatabase { if user.server_name() != services().globals.server_name() { - info!(?user, "Migration: creating user"); + t::info!(?user, "Migration: creating user"); services().users.create(&user, None)?; } } @@ -718,7 +718,7 @@ impl KeyValueDatabase { let shortroomid = services().globals.next_count()?.to_be_bytes(); self.roomid_shortroomid.insert(&room_id, &shortroomid)?; - info!("Migration: 8"); + t::info!("Migration: 8"); } // Update pduids db layout let mut batch = self.pduid_pdu.iter().filter_map(|(key, v)| { @@ -799,10 +799,10 @@ impl KeyValueDatabase { while iter.peek().is_some() { self.tokenids .insert_batch(&mut iter.by_ref().take(1000))?; - debug!("Inserted smaller batch"); + t::debug!("Inserted smaller batch"); } - info!("Deleting starts"); + t::info!("Deleting starts"); let batch2: Vec<_> = self .tokenids @@ -848,7 +848,7 @@ impl KeyValueDatabase { ) { Ok(u) => u, Err(error) => { - warn!( + t::warn!( %error, user_localpart = %username, "Invalid username", @@ -950,7 +950,7 @@ impl KeyValueDatabase { ) { Ok(u) => u, Err(error) => { - warn!( + t::warn!( %error, user_localpart = %username, "Invalid username", @@ -1002,7 +1002,7 @@ impl KeyValueDatabase { "database should be migrated to the current version", ); - info!( + t::info!( backend = %services().globals.config.database.backend, version = latest_database_version, "Loaded database", @@ -1015,7 +1015,7 @@ impl KeyValueDatabase { // Create the admin room and server user on first run services().admin.create_admin_room().await?; - info!( + t::info!( backend = %services().globals.config.database.backend, version = latest_database_version, "Created new database", @@ -1025,7 +1025,7 @@ impl KeyValueDatabase { Ok(()) } - #[tracing::instrument] + #[t::instrument] pub(crate) fn start_cleanup_task() { use std::time::{Duration, Instant}; @@ -1046,28 +1046,31 @@ impl KeyValueDatabase { #[cfg(unix)] let msg = tokio::select! { _ = i.tick() => || { - debug!("cleanup: Timer ticked"); + t::debug!("cleanup: Timer ticked"); }, _ = s.recv() => || { - debug!("cleanup: Received SIGHUP"); + t::debug!("cleanup: Received SIGHUP"); }, }; #[cfg(not(unix))] let msg = { i.tick().await; - || debug!("cleanup: Timer ticked") + || t::debug!("cleanup: Timer ticked") }; async { msg(); let start = Instant::now(); if let Err(error) = services().globals.cleanup() { - error!(%error, "cleanup: Error"); + t::error!(%error, "cleanup: Error"); } else { - debug!(elapsed = ?start.elapsed(), "cleanup: Finished"); + t::debug!( + elapsed = ?start.elapsed(), + "cleanup: Finished" + ); } } - .instrument(info_span!("database_cleanup")) + .instrument(t::info_span!("database_cleanup")) .await; } }); @@ -1084,7 +1087,7 @@ where if current_version < new_version { migration()?; services().globals.bump_database_version(new_version)?; - warn!("Migration: {current_version} -> {new_version} finished"); + t::warn!("Migration: {current_version} -> {new_version} finished"); } Ok(()) } diff --git a/src/database/abstraction/rocksdb.rs b/src/database/abstraction/rocksdb.rs index 90cdb06a..f907ecd8 100644 --- a/src/database/abstraction/rocksdb.rs +++ b/src/database/abstraction/rocksdb.rs @@ -10,12 +10,11 @@ use rocksdb::{ DBCompactionStyle, DBCompressionType, DBRecoveryMode, DBWithThreadMode, Direction, IteratorMode, MultiThreaded, Options, ReadOptions, WriteOptions, }; -use tracing::Level; use super::{ super::Config, watchers::Watchers, KeyValueDatabaseEngine, KvTree, }; -use crate::{utils, Result}; +use crate::{observability::prelude::*, utils, Result}; pub(crate) struct Engine { rocks: DBWithThreadMode, @@ -151,14 +150,14 @@ impl RocksDbEngineTree<'_> { } impl KvTree for RocksDbEngineTree<'_> { - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn get(&self, key: &[u8]) -> Result>> { let readoptions = ReadOptions::default(); Ok(self.db.rocks.get_cf_opt(&self.cf(), key, &readoptions)?) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn insert(&self, key: &[u8], value: &[u8]) -> Result<()> { let writeoptions = WriteOptions::default(); let lock = self.write_lock.read().unwrap(); @@ -170,7 +169,7 @@ impl KvTree for RocksDbEngineTree<'_> { Ok(()) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn insert_batch( &self, iter: &mut dyn Iterator, Vec)>, @@ -183,13 +182,13 @@ impl KvTree for RocksDbEngineTree<'_> { Ok(()) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn remove(&self, key: &[u8]) -> Result<()> { let writeoptions = WriteOptions::default(); Ok(self.db.rocks.delete_cf_opt(&self.cf(), key, &writeoptions)?) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn iter<'a>(&'a self) -> Box, Vec)> + 'a> { let readoptions = ReadOptions::default(); @@ -202,7 +201,7 @@ impl KvTree for RocksDbEngineTree<'_> { ) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn iter_from<'a>( &'a self, from: &[u8], @@ -230,7 +229,7 @@ impl KvTree for RocksDbEngineTree<'_> { ) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn increment(&self, key: &[u8]) -> Result> { let readoptions = ReadOptions::default(); let writeoptions = WriteOptions::default(); @@ -245,7 +244,7 @@ impl KvTree for RocksDbEngineTree<'_> { Ok(new) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn increment_batch( &self, iter: &mut dyn Iterator>, @@ -267,7 +266,7 @@ impl KvTree for RocksDbEngineTree<'_> { Ok(()) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn scan_prefix<'a>( &'a self, prefix: Vec, @@ -288,7 +287,7 @@ impl KvTree for RocksDbEngineTree<'_> { ) } - #[tracing::instrument(level = Level::TRACE, skip_all)] + #[t::instrument(level = t::Level::TRACE, skip_all)] fn watch_prefix<'a>( &'a self, prefix: &[u8], diff --git a/src/database/abstraction/sqlite.rs b/src/database/abstraction/sqlite.rs index 402e8621..ba853856 100644 --- a/src/database/abstraction/sqlite.rs +++ b/src/database/abstraction/sqlite.rs @@ -9,10 +9,9 @@ use std::{ use parking_lot::{Mutex, MutexGuard}; use rusqlite::{Connection, DatabaseName::Main, OptionalExtension}; use thread_local::ThreadLocal; -use tracing::debug; use super::{watchers::Watchers, KeyValueDatabaseEngine, KvTree}; -use crate::{database::Config, Result}; +use crate::{database::Config, observability::prelude::*, Result}; thread_local! { static READ_CONNECTION: RefCell> = @@ -397,11 +396,11 @@ impl KvTree for SqliteTable { } fn clear(&self) -> Result<()> { - debug!("clear: running"); + t::debug!("clear: running"); self.engine .write_lock() .execute(format!("DELETE FROM {}", self.name).as_str(), [])?; - debug!("clear: ran"); + t::debug!("clear: ran"); Ok(()) } } diff --git a/src/database/key_value/account_data.rs b/src/database/key_value/account_data.rs index 9033ac90..002bb80a 100644 --- a/src/database/key_value/account_data.rs +++ b/src/database/key_value/account_data.rs @@ -8,13 +8,14 @@ use ruma::{ }; use crate::{ - database::KeyValueDatabase, service, services, utils, Error, Result, + database::KeyValueDatabase, observability::prelude::*, service, services, + utils, Error, Result, }; impl service::account_data::Data for KeyValueDatabase { /// Places one event in the account data of the user and removes the /// previous entry. - #[tracing::instrument(skip(self, room_id, user_id, event_type, data))] + #[t::instrument(skip(self, room_id, user_id, event_type, data))] fn update( &self, room_id: Option<&RoomId>, @@ -66,7 +67,7 @@ impl service::account_data::Data for KeyValueDatabase { } /// Searches the account data for a specific kind. - #[tracing::instrument(skip(self, room_id, user_id, kind))] + #[t::instrument(skip(self, room_id, user_id, kind))] fn get( &self, room_id: Option<&RoomId>, @@ -97,7 +98,7 @@ impl service::account_data::Data for KeyValueDatabase { } /// Returns all changes to the account data that happened after `since`. - #[tracing::instrument(skip(self, room_id, user_id, since))] + #[t::instrument(skip(self, room_id, user_id, since))] fn changes_since( &self, room_id: Option<&RoomId>, diff --git a/src/database/key_value/globals.rs b/src/database/key_value/globals.rs index e3293571..841a540a 100644 --- a/src/database/key_value/globals.rs +++ b/src/database/key_value/globals.rs @@ -8,6 +8,7 @@ use ruma::{ use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{self, globals::SigningKeys}, services, utils, Error, Result, }; @@ -28,7 +29,7 @@ impl service::globals::Data for KeyValueDatabase { }) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] async fn watch( &self, user_id: &UserId, diff --git a/src/database/key_value/media.rs b/src/database/key_value/media.rs index 53e2146e..cb41ccb7 100644 --- a/src/database/key_value/media.rs +++ b/src/database/key_value/media.rs @@ -2,6 +2,7 @@ use ruma::OwnedMxcUri; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{ self, media::{FileMeta, MediaFileKey}, @@ -20,7 +21,7 @@ struct MediaFileKeyParts { impl TryFrom<&MediaFileKey> for MediaFileKeyParts { type Error = Error; - #[tracing::instrument( + #[t::instrument( err, fields(key = utils::u8_slice_to_hex(key.as_bytes())), )] diff --git a/src/database/key_value/rooms/alias.rs b/src/database/key_value/rooms/alias.rs index a1355ed2..edd38180 100644 --- a/src/database/key_value/rooms/alias.rs +++ b/src/database/key_value/rooms/alias.rs @@ -4,11 +4,12 @@ use ruma::{ }; use crate::{ - database::KeyValueDatabase, service, services, utils, Error, Result, + database::KeyValueDatabase, observability::prelude::*, service, services, + utils, Error, Result, }; impl service::rooms::alias::Data for KeyValueDatabase { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn set_alias(&self, alias: &RoomAliasId, room_id: &RoomId) -> Result<()> { self.alias_roomid .insert(alias.alias().as_bytes(), room_id.as_bytes())?; @@ -20,7 +21,7 @@ impl service::rooms::alias::Data for KeyValueDatabase { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn remove_alias(&self, alias: &RoomAliasId) -> Result<()> { if let Some(room_id) = self.alias_roomid.get(alias.alias().as_bytes())? @@ -41,7 +42,7 @@ impl service::rooms::alias::Data for KeyValueDatabase { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn resolve_local_alias( &self, alias: &RoomAliasId, @@ -63,7 +64,7 @@ impl service::rooms::alias::Data for KeyValueDatabase { .transpose() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn local_aliases_for_room<'a>( &'a self, room_id: &RoomId, diff --git a/src/database/key_value/rooms/auth_chain.rs b/src/database/key_value/rooms/auth_chain.rs index b736e524..bf788cba 100644 --- a/src/database/key_value/rooms/auth_chain.rs +++ b/src/database/key_value/rooms/auth_chain.rs @@ -2,12 +2,13 @@ use std::{collections::HashSet, mem::size_of}; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{self, rooms::short::ShortEventId}, utils, Result, }; impl service::rooms::auth_chain::Data for KeyValueDatabase { - #[tracing::instrument(skip(self, key))] + #[t::instrument(skip(self, key))] fn get_cached_eventid_authchain( &self, key: &[ShortEventId], diff --git a/src/database/key_value/rooms/directory.rs b/src/database/key_value/rooms/directory.rs index 58964927..4c130a57 100644 --- a/src/database/key_value/rooms/directory.rs +++ b/src/database/key_value/rooms/directory.rs @@ -1,24 +1,27 @@ use ruma::{OwnedRoomId, RoomId}; -use crate::{database::KeyValueDatabase, service, utils, Error, Result}; +use crate::{ + database::KeyValueDatabase, observability::prelude::*, service, utils, + Error, Result, +}; impl service::rooms::directory::Data for KeyValueDatabase { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn set_public(&self, room_id: &RoomId) -> Result<()> { self.publicroomids.insert(room_id.as_bytes(), &[]) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn set_not_public(&self, room_id: &RoomId) -> Result<()> { self.publicroomids.remove(room_id.as_bytes()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn is_public_room(&self, room_id: &RoomId) -> Result { Ok(self.publicroomids.get(room_id.as_bytes())?.is_some()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn public_rooms<'a>( &'a self, ) -> Box> + 'a> { diff --git a/src/database/key_value/rooms/edus/read_receipt.rs b/src/database/key_value/rooms/edus/read_receipt.rs index f8e1470f..f7c232a9 100644 --- a/src/database/key_value/rooms/edus/read_receipt.rs +++ b/src/database/key_value/rooms/edus/read_receipt.rs @@ -4,11 +4,12 @@ use ruma::{ }; use crate::{ - database::KeyValueDatabase, service, services, utils, Error, Result, + database::KeyValueDatabase, observability::prelude::*, service, services, + utils, Error, Result, }; impl service::rooms::edus::read_receipt::Data for KeyValueDatabase { - #[tracing::instrument(skip(self, event))] + #[t::instrument(skip(self, event))] fn readreceipt_update( &self, user_id: &UserId, @@ -52,7 +53,7 @@ impl service::rooms::edus::read_receipt::Data for KeyValueDatabase { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] #[allow(clippy::type_complexity)] fn readreceipts_since<'a>( &'a self, @@ -126,7 +127,7 @@ impl service::rooms::edus::read_receipt::Data for KeyValueDatabase { ) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn private_read_set( &self, room_id: &RoomId, @@ -143,7 +144,7 @@ impl service::rooms::edus::read_receipt::Data for KeyValueDatabase { .insert(&key, &services().globals.next_count()?.to_be_bytes()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn private_read_get( &self, room_id: &RoomId, diff --git a/src/database/key_value/rooms/metadata.rs b/src/database/key_value/rooms/metadata.rs index dc8c7a19..046c2b27 100644 --- a/src/database/key_value/rooms/metadata.rs +++ b/src/database/key_value/rooms/metadata.rs @@ -1,11 +1,12 @@ use ruma::{OwnedRoomId, RoomId}; use crate::{ - database::KeyValueDatabase, service, services, utils, Error, Result, + database::KeyValueDatabase, observability::prelude::*, service, services, + utils, Error, Result, }; impl service::rooms::metadata::Data for KeyValueDatabase { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn exists(&self, room_id: &RoomId) -> Result { let prefix = match services().rooms.short.get_shortroomid(room_id)? { Some(b) => b.get().to_be_bytes().to_vec(), diff --git a/src/database/key_value/rooms/outlier.rs b/src/database/key_value/rooms/outlier.rs index 562331ef..7b2ae2a7 100644 --- a/src/database/key_value/rooms/outlier.rs +++ b/src/database/key_value/rooms/outlier.rs @@ -1,6 +1,9 @@ use ruma::{CanonicalJsonObject, EventId}; -use crate::{database::KeyValueDatabase, service, Error, Result}; +use crate::{ + database::KeyValueDatabase, observability::prelude::*, service, Error, + Result, +}; impl service::rooms::outlier::Data for KeyValueDatabase { fn get_outlier_pdu_json( @@ -16,7 +19,7 @@ impl service::rooms::outlier::Data for KeyValueDatabase { ) } - #[tracing::instrument(skip(self, pdu))] + #[t::instrument(skip(self, pdu))] fn add_pdu_outlier( &self, event_id: &EventId, diff --git a/src/database/key_value/rooms/search.rs b/src/database/key_value/rooms/search.rs index 510feca5..e3dc569c 100644 --- a/src/database/key_value/rooms/search.rs +++ b/src/database/key_value/rooms/search.rs @@ -2,6 +2,7 @@ use ruma::RoomId; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{ self, rooms::{short::ShortRoomId, timeline::PduId}, @@ -21,7 +22,7 @@ fn tokenize(body: &str) -> impl Iterator + '_ { } impl service::rooms::search::Data for KeyValueDatabase { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn index_pdu( &self, shortroomid: ShortRoomId, @@ -40,7 +41,7 @@ impl service::rooms::search::Data for KeyValueDatabase { self.tokenids.insert_batch(&mut batch) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn deindex_pdu( &self, shortroomid: ShortRoomId, @@ -63,7 +64,7 @@ impl service::rooms::search::Data for KeyValueDatabase { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] #[allow(clippy::type_complexity)] fn search_pdus<'a>( &'a self, diff --git a/src/database/key_value/rooms/short.rs b/src/database/key_value/rooms/short.rs index ee137733..bc5cb09d 100644 --- a/src/database/key_value/rooms/short.rs +++ b/src/database/key_value/rooms/short.rs @@ -4,6 +4,7 @@ use ruma::{events::StateEventType, EventId, RoomId}; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{ self, rooms::short::{ @@ -14,7 +15,7 @@ use crate::{ }; impl service::rooms::short::Data for KeyValueDatabase { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_or_create_shorteventid( &self, event_id: &EventId, @@ -40,7 +41,7 @@ impl service::rooms::short::Data for KeyValueDatabase { Ok((ShortEventId::new(short), created)) } - #[tracing::instrument(skip(self), fields(cache_result))] + #[t::instrument(skip(self), fields(cache_result))] fn get_shortstatekey( &self, event_type: &StateEventType, @@ -65,7 +66,7 @@ impl service::rooms::short::Data for KeyValueDatabase { Ok(short) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_or_create_shortstatekey( &self, event_type: &StateEventType, @@ -98,7 +99,7 @@ impl service::rooms::short::Data for KeyValueDatabase { Ok((short, created)) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_eventid_from_short( &self, shorteventid: ShortEventId, @@ -124,7 +125,7 @@ impl service::rooms::short::Data for KeyValueDatabase { Ok(event_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_statekey_from_short( &self, shortstatekey: ShortStateKey, @@ -162,7 +163,7 @@ impl service::rooms::short::Data for KeyValueDatabase { } /// Returns `(shortstatehash, already_existed)` - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_or_create_shortstatehash( &self, state_hash: &[u8], diff --git a/src/database/key_value/rooms/state_cache.rs b/src/database/key_value/rooms/state_cache.rs index c90a18b1..8c2ad2f7 100644 --- a/src/database/key_value/rooms/state_cache.rs +++ b/src/database/key_value/rooms/state_cache.rs @@ -8,6 +8,7 @@ use ruma::{ use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{self, appservice::RegistrationInfo}, services, utils, Error, Result, }; @@ -166,7 +167,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { Ok(real_users) } - #[tracing::instrument( + #[t::instrument( skip(self, appservice), fields(appservice_id = appservice.registration.id), )] @@ -193,7 +194,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { } /// Makes a user forget a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn forget(&self, room_id: &RoomId, user_id: &UserId) -> Result<()> { let mut userroom_id = user_id.as_bytes().to_vec(); userroom_id.push(0xFF); @@ -210,7 +211,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { } /// Returns an iterator of all servers participating in this room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn room_servers<'a>( &'a self, room_id: &RoomId, @@ -237,7 +238,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { })) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn server_in_room( &self, server: &ServerName, @@ -252,7 +253,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { /// Returns an iterator of all rooms a server participates in (as far as we /// know). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn server_rooms<'a>( &'a self, server: &ServerName, @@ -280,7 +281,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { } /// Returns an iterator over all joined members of a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn room_members<'a>( &'a self, room_id: &RoomId, @@ -307,7 +308,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { })) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn room_joined_count(&self, room_id: &RoomId) -> Result> { self.roomid_joinedcount .get(room_id.as_bytes())? @@ -319,7 +320,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { .transpose() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn room_invited_count(&self, room_id: &RoomId) -> Result> { self.roomid_invitedcount .get(room_id.as_bytes())? @@ -332,7 +333,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { } /// Returns an iterator over all invited members of a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn room_members_invited<'a>( &'a self, room_id: &RoomId, @@ -363,7 +364,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { )) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_invite_count( &self, room_id: &RoomId, @@ -380,7 +381,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { }) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_left_count( &self, room_id: &RoomId, @@ -401,7 +402,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { } /// Returns an iterator over all rooms this user joined. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn rooms_joined<'a>( &'a self, user_id: &UserId, @@ -434,7 +435,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { /// Returns an iterator over all rooms a user was invited to. #[allow(clippy::type_complexity)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn rooms_invited<'a>( &'a self, user_id: &UserId, @@ -477,7 +478,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { )) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn invite_state( &self, user_id: &UserId, @@ -501,7 +502,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { .transpose() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn left_state( &self, user_id: &UserId, @@ -527,7 +528,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { /// Returns an iterator over all rooms a user left. #[allow(clippy::type_complexity)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn rooms_left<'a>( &'a self, user_id: &UserId, @@ -569,7 +570,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { )) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn once_joined(&self, user_id: &UserId, room_id: &RoomId) -> Result { let mut userroom_id = user_id.as_bytes().to_vec(); userroom_id.push(0xFF); @@ -578,7 +579,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { Ok(self.roomuseroncejoinedids.get(&userroom_id)?.is_some()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn is_joined(&self, user_id: &UserId, room_id: &RoomId) -> Result { let mut userroom_id = user_id.as_bytes().to_vec(); userroom_id.push(0xFF); @@ -587,7 +588,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { Ok(self.userroomid_joined.get(&userroom_id)?.is_some()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn is_invited(&self, user_id: &UserId, room_id: &RoomId) -> Result { let mut userroom_id = user_id.as_bytes().to_vec(); userroom_id.push(0xFF); @@ -596,7 +597,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase { Ok(self.userroomid_invitestate.get(&userroom_id)?.is_some()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn is_left(&self, user_id: &UserId, room_id: &RoomId) -> Result { let mut userroom_id = user_id.as_bytes().to_vec(); userroom_id.push(0xFF); diff --git a/src/database/key_value/rooms/timeline.rs b/src/database/key_value/rooms/timeline.rs index b46e9bfe..e2a91ca0 100644 --- a/src/database/key_value/rooms/timeline.rs +++ b/src/database/key_value/rooms/timeline.rs @@ -8,6 +8,7 @@ use service::rooms::timeline::PduCount; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{self, rooms::timeline::PduId}, services, utils, Error, PduEvent, Result, }; @@ -89,7 +90,7 @@ impl service::rooms::timeline::Data for KeyValueDatabase { /// Returns the pdu. /// /// Checks the `eventid_outlierpdu` Tree if not found in the timeline. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_pdu(&self, event_id: &EventId) -> Result>> { Ok(self .get_non_outlier_pdu(event_id)? diff --git a/src/database/key_value/sending.rs b/src/database/key_value/sending.rs index 1f7db867..eedcf9a3 100644 --- a/src/database/key_value/sending.rs +++ b/src/database/key_value/sending.rs @@ -2,6 +2,7 @@ use ruma::{serde::Raw, ServerName, UserId}; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{ self, rooms::timeline::PduId, @@ -130,7 +131,7 @@ impl service::sending::Data for KeyValueDatabase { } } -#[tracing::instrument(skip(key, value))] +#[t::instrument(skip(key, value))] fn parse_servercurrentevent( key: &RequestKey, value: Vec, diff --git a/src/database/key_value/users.rs b/src/database/key_value/users.rs index e3fdb95e..7967208b 100644 --- a/src/database/key_value/users.rs +++ b/src/database/key_value/users.rs @@ -9,10 +9,10 @@ use ruma::{ OwnedDeviceId, OwnedKeyId, OwnedMxcUri, OwnedOneTimeKeyId, OwnedUserId, UInt, UserId, }; -use tracing::warn; use crate::{ database::KeyValueDatabase, + observability::prelude::*, service::{self, users::clean_signatures}, services, utils, Error, Result, }; @@ -490,7 +490,7 @@ impl service::users::Data for KeyValueDatabase { Ok(counts) } - #[tracing::instrument(skip(self, device_keys))] + #[t::instrument(skip(self, device_keys))] fn add_device_keys( &self, user_id: &UserId, @@ -512,7 +512,7 @@ impl service::users::Data for KeyValueDatabase { Ok(()) } - #[tracing::instrument(skip( + #[t::instrument(skip( self, master_key, self_signing_key, @@ -700,14 +700,14 @@ impl service::users::Data for KeyValueDatabase { if let Ok(c) = utils::u64_from_bytes(current) { c <= to } else { - warn!( + t::warn!( "BadDatabase: Could not parse \ keychangeid_userid bytes" ); false } } else { - warn!( + t::warn!( "BadDatabase: Could not parse \ keychangeid_userid" ); @@ -732,7 +732,7 @@ impl service::users::Data for KeyValueDatabase { ) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn mark_device_key_update(&self, user_id: &UserId) -> Result<()> { let count = services().globals.next_count()?.to_be_bytes(); for room_id in services() @@ -1102,7 +1102,7 @@ fn get_username_with_valid_password( match utils::string_from_bytes(username) { Ok(u) => Some(u), Err(e) => { - warn!( + t::warn!( "Failed to parse username while calling \ get_local_users(): {}", e.to_string() diff --git a/src/error.rs b/src/error.rs index ed8c2208..87105ae2 100644 --- a/src/error.rs +++ b/src/error.rs @@ -4,7 +4,7 @@ use std::path::PathBuf; use thiserror::Error; -use crate::config::ListenConfig; +use crate::{config::ListenConfig, observability::prelude::*}; /// Top-level errors // Missing docs are allowed here since that kind of information should be @@ -16,7 +16,7 @@ pub(crate) enum Main { ServeCommand(#[from] ServeCommand), #[error("failed to install global default tracing subscriber")] - SetSubscriber(#[from] tracing::subscriber::SetGlobalDefaultError), + SetSubscriber(#[from] t::subscriber::SetGlobalDefaultError), #[error(transparent)] CheckConfigCommand(#[from] CheckConfigCommand), @@ -84,7 +84,7 @@ pub(crate) enum Observability { Otel(#[from] opentelemetry::trace::TraceError), #[error("failed to install global default tracing subscriber")] - SetSubscriber(#[from] tracing::subscriber::SetGlobalDefaultError), + SetSubscriber(#[from] t::subscriber::SetGlobalDefaultError), // Upstream's documentation on what this error means is very sparse #[error("tracing_flame error")] diff --git a/src/main.rs b/src/main.rs index a0930e73..12ac626d 100644 --- a/src/main.rs +++ b/src/main.rs @@ -7,9 +7,10 @@ use std::process::ExitCode; use clap::Parser; #[cfg(all(not(target_env = "msvc"), feature = "jemalloc"))] use tikv_jemallocator::Jemalloc; -use tracing::{error, info}; use wee_woo::ErrorExt; +use crate::observability::prelude::*; + mod api; mod cli; mod config; @@ -50,7 +51,7 @@ enum ApplicationState { } fn set_application_state(state: ApplicationState) { - info!(?state, "Application state changed"); + t::info!(?state, "Application state changed"); #[cfg(feature = "systemd")] { @@ -107,20 +108,19 @@ async fn main() -> ExitCode { } #[cfg(unix)] -#[tracing::instrument(err)] +#[t::instrument(err)] fn maximize_fd_limit() -> Result<(), nix::errno::Errno> { use nix::sys::resource::{getrlimit, setrlimit, Resource}; - use tracing::debug; let res = Resource::RLIMIT_NOFILE; let (soft_limit, hard_limit) = getrlimit(res)?; - debug!(soft_limit, "Current nofile soft limit"); + t::debug!(soft_limit, "Current nofile soft limit"); setrlimit(res, hard_limit, hard_limit)?; - debug!(hard_limit, "Increased nofile soft limit to the hard limit"); + t::debug!(hard_limit, "Increased nofile soft limit to the hard limit"); Ok(()) } diff --git a/src/observability.rs b/src/observability.rs index 9f3bca7a..e0da5c3a 100644 --- a/src/observability.rs +++ b/src/observability.rs @@ -23,7 +23,7 @@ use opentelemetry_sdk::{ use strum::{AsRefStr, IntoStaticStr}; use thiserror::Error; use tokio::time::Instant; -use tracing::{subscriber::SetGlobalDefaultError, Span}; +use tracing::subscriber::SetGlobalDefaultError; use tracing_flame::{FlameLayer, FlushGuard}; use tracing_opentelemetry::OtelData; use tracing_subscriber::{ @@ -35,6 +35,7 @@ use tracing_subscriber::{ use crate::{ config::{Config, EnvFilterClone, LogFormat}, error, + observability::prelude::*, utils::error::Result, }; @@ -314,7 +315,7 @@ pub(crate) fn init( .with(traces_layer) .with(flame_layer) .with(log_layer); - tracing::subscriber::set_global_default(subscriber)?; + t::subscriber::set_global_default(subscriber)?; Ok(( Guard { @@ -499,8 +500,8 @@ pub(crate) async fn http_metrics_layer(req: Request, next: Next) -> Response { pub(crate) async fn traceresponse_layer(req: Request, next: Next) -> Response { let mut resp = next.run(req).await; - let ids = tracing::dispatcher::get_default(|dispatch| { - Span::current() + let ids = t::dispatcher::get_default(|dispatch| { + t::Span::current() .id() .and_then(|id| { dispatch @@ -557,5 +558,5 @@ pub(crate) fn init_for_cli( let subscriber = Registry::default().with(log_layer); - tracing::subscriber::set_global_default(subscriber).map_err(Into::into) + t::subscriber::set_global_default(subscriber).map_err(Into::into) } diff --git a/src/observability/prelude.rs b/src/observability/prelude.rs index 63d39bca..a991e8f7 100644 --- a/src/observability/prelude.rs +++ b/src/observability/prelude.rs @@ -8,7 +8,6 @@ //! This avoids diff churn in the imports when adding/removing log statements. //! //! [`tracing`] is re-exported as `t`, to avoid name collisions. -#![allow(unused)] pub(crate) use tracing as t; pub(crate) use tracing::Instrument; diff --git a/src/service/admin.rs b/src/service/admin.rs index 5e3ee770..2567c9d7 100644 --- a/src/service/admin.rs +++ b/src/service/admin.rs @@ -28,11 +28,11 @@ use ruma::{ }; use serde_json::value::to_raw_value; use tokio::sync::{mpsc, Mutex, RwLock}; -use tracing::warn; use super::pdu::PduBuilder; use crate::{ api::client_server::{leave_all_rooms, AUTO_GEN_PASSWORD_LENGTH}, + observability::prelude::*, services, utils::{self, dbg_truncate_str, room_version::RoomVersion}, Error, PduEvent, Result, @@ -289,7 +289,7 @@ impl Service { }); } - #[tracing::instrument(skip(self, grapevine_room))] + #[t::instrument(skip(self, grapevine_room))] async fn handle_event( &self, event: AdminRoomEvent, @@ -327,7 +327,7 @@ impl Service { .unwrap(); } - #[tracing::instrument( + #[t::instrument( skip(self, room_message), fields( room_message = dbg_truncate_str(&room_message, 50).as_ref(), @@ -337,7 +337,7 @@ impl Service { self.sender.send(AdminRoomEvent::ProcessMessage(room_message)).unwrap(); } - #[tracing::instrument(skip(self, message_content))] + #[t::instrument(skip(self, message_content))] pub(crate) fn send_message( &self, message_content: RoomMessageEventContent, @@ -346,7 +346,7 @@ impl Service { } // Parse and process a message from the admin room - #[tracing::instrument( + #[t::instrument( skip(self, room_message), fields( room_message = dbg_truncate_str(&room_message, 50).as_ref(), @@ -397,7 +397,7 @@ impl Service { } // Parse chat messages from the admin room into an AdminCommand object - #[tracing::instrument( + #[t::instrument( skip(command_line), fields( command_line = dbg_truncate_str(command_line, 50).as_ref(), @@ -428,7 +428,7 @@ impl Service { } #[allow(clippy::too_many_lines)] - #[tracing::instrument(skip(self, body))] + #[t::instrument(skip(self, body))] async fn process_admin_command( &self, command: AdminCommand, @@ -1068,7 +1068,11 @@ impl Service { if leave_rooms { for &user_id in &user_ids { if let Err(error) = leave_all_rooms(user_id).await { - warn!(%user_id, %error, "failed to leave one or more rooms"); + t::warn!( + %user_id, + %error, + "failed to leave one or more rooms" + ); } } } @@ -1253,7 +1257,7 @@ impl Service { } // Utility to turn clap's `--help` text to HTML. - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] fn usage_to_html(text: &str, server_name: &ServerName) -> String { // Replace `@grapevine:servername:-subcmdname` with // `@grapevine:servername: subcmdname` @@ -1334,7 +1338,7 @@ impl Service { /// be used to issue admin commands by talking to the server user inside /// it. #[allow(clippy::too_many_lines)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn create_admin_room(&self) -> Result<()> { let room_id = RoomId::new(services().globals.server_name()); @@ -1586,7 +1590,7 @@ impl Service { /// Invite the user to the grapevine admin room. /// /// In grapevine, this is equivalent to granting admin privileges. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn make_user_admin( &self, user_id: &UserId, diff --git a/src/service/appservice.rs b/src/service/appservice.rs index 8174d2e4..35f00c6a 100644 --- a/src/service/appservice.rs +++ b/src/service/appservice.rs @@ -8,7 +8,7 @@ use ruma::{ }; use tokio::sync::RwLock; -use crate::Result; +use crate::{observability::prelude::*, Result}; mod data; @@ -137,7 +137,7 @@ impl Service { } /// Registers an appservice and returns the ID to the caller. - #[tracing::instrument(skip(self, yaml), fields(appservice_id = yaml.id))] + #[t::instrument(skip(self, yaml), fields(appservice_id = yaml.id))] pub(crate) async fn register_appservice( &self, yaml: Registration, @@ -156,7 +156,7 @@ impl Service { /// # Arguments /// /// * `service_name` - the name you send to register the service previously - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn unregister_appservice( &self, service_name: &str, @@ -168,7 +168,7 @@ impl Service { self.db.unregister_appservice(service_name) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn get_registration( &self, id: &str, @@ -185,7 +185,7 @@ impl Service { self.registration_info.read().await.keys().cloned().collect() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn find_from_token( &self, token: &str, @@ -198,7 +198,7 @@ impl Service { } // Checks if a given user id matches any exclusive appservice regex - #[tracing::instrument(skip(self), ret(level = "trace"))] + #[t::instrument(skip(self), ret(level = "trace"))] pub(crate) async fn is_exclusive_user_id(&self, user_id: &UserId) -> bool { self.read() .await @@ -207,7 +207,7 @@ impl Service { } // Checks if a given room alias matches any exclusive appservice regex - #[tracing::instrument(skip(self), ret(level = "trace"))] + #[t::instrument(skip(self), ret(level = "trace"))] pub(crate) async fn is_exclusive_alias(&self, alias: &RoomAliasId) -> bool { self.read() .await diff --git a/src/service/globals.rs b/src/service/globals.rs index ea1dce4f..7b5f6ff4 100644 --- a/src/service/globals.rs +++ b/src/service/globals.rs @@ -34,13 +34,12 @@ use ruma::{ ServerName, UInt, UserId, }; use tokio::sync::{broadcast, Mutex, RwLock, Semaphore}; -use tracing::{error, warn, Instrument}; use trust_dns_resolver::TokioAsyncResolver; use crate::{ api::server_server::FedDest, config::{MediaBackendConfig, MediaFilesystemConfig}, - observability::FilterReloadHandles, + observability::{prelude::*, FilterReloadHandles}, service::media::MediaFileKey, services, utils::on_demand_hashmap::{OnDemandHashMap, TokenSet}, @@ -156,7 +155,7 @@ impl Resolver { } impl Resolve for Resolver { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn resolve(&self, name: Name) -> Resolving { self.overrides .read() @@ -197,7 +196,7 @@ impl Resolve for Resolver { } impl Service { - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) fn new( db: &'static dyn Data, config: Config, @@ -208,7 +207,7 @@ impl Service { let keypair = match keypair { Ok(k) => k, Err(e) => { - error!("Keypair invalid. Deleting..."); + t::error!("Keypair invalid. Deleting..."); db.remove_keypair()?; return Err(e); } @@ -257,7 +256,7 @@ impl Service { keypair: Arc::new(keypair), dns_resolver: TokioAsyncResolver::tokio_from_system_conf() .map_err(|e| { - error!( + t::error!( "Failed to set up trust dns resolver with system \ config: {}", e @@ -300,7 +299,12 @@ impl Service { if !s.supported_room_versions().contains(&s.config.default_room_version) { - error!(config=?s.config.default_room_version, fallback=?crate::config::default_default_room_version(), "Room version in config isn't supported, falling back to default version"); + t::error!( + config=?s.config.default_room_version, + fallback=?crate::config::default_default_room_version(), + "Room version in config isn't supported, falling back to \ + default version" + ); s.config.default_room_version = crate::config::default_default_room_version(); }; @@ -356,12 +360,12 @@ impl Service { self.federation_client.clone() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn next_count(&self) -> Result { self.db.next_count() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn current_count(&self) -> Result { self.db.current_count() } @@ -483,7 +487,7 @@ impl Service { match inner() { Ok(pwd_set) => { if pwd_set { - warn!( + t::warn!( "The Grapevine account emergency password is set! \ Please unset it as soon as you finish admin account \ recovery!" @@ -498,7 +502,7 @@ impl Service { } } Err(error) => { - error!( + t::error!( %error, "Could not set the configured emergency password for the \ Grapevine user", diff --git a/src/service/media.rs b/src/service/media.rs index 9b965caa..2ea69782 100644 --- a/src/service/media.rs +++ b/src/service/media.rs @@ -9,9 +9,8 @@ use tokio::{ fs::{self, File}, io::{AsyncReadExt, AsyncWriteExt}, }; -use tracing::{debug, warn}; -use crate::{services, utils, Error, Result}; +use crate::{observability::prelude::*, services, utils, Error, Result}; mod data; @@ -47,7 +46,7 @@ pub(crate) struct Service { impl Service { /// Uploads a file. - #[tracing::instrument(skip(self, file))] + #[t::instrument(skip(self, file))] pub(crate) async fn create( &self, mxc: OwnedMxcUri, @@ -68,7 +67,7 @@ impl Service { } /// Uploads or replaces a file thumbnail. - #[tracing::instrument(skip(self, file))] + #[t::instrument(skip(self, file))] pub(crate) async fn upload_thumbnail( &self, mxc: OwnedMxcUri, @@ -89,7 +88,7 @@ impl Service { } /// Downloads a file. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn get( &self, mxc: OwnedMxcUri, @@ -102,7 +101,7 @@ impl Service { } /// Deletes a media object and all associated thumbnails. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn delete(&self, mxc: OwnedMxcUri) -> Result<()> { let mut any_files = false; @@ -111,7 +110,7 @@ impl Service { any_files = true; self.delete_by_key(thumbnail_key.clone()).await.inspect_err( |error| { - warn!( + t::warn!( thumbnail_key = utils::u8_slice_to_hex( thumbnail_key.as_bytes() ), @@ -124,12 +123,12 @@ impl Service { if let Some((_, key)) = self.db.search_file_metadata(mxc, 0, 0).inspect_err( - |error| warn!(%error, "Failed to find original media key"), + |error| t::warn!(%error, "Failed to find original media key"), )? { any_files = true; self.delete_by_key(key).await.inspect_err( - |error| warn!(%error, "Failed to delete original media"), + |error| t::warn!(%error, "Failed to delete original media"), )?; } @@ -138,7 +137,7 @@ impl Service { } else { let error = Error::BadRequest(ErrorKind::NotFound, "Media not found"); - warn!(%error, "Failed to delete media"); + t::warn!(%error, "Failed to delete media"); Err(error) } } @@ -167,7 +166,7 @@ impl Service { /// /// Each MXC is listed once. Thumbnails are not included separately from the /// original media. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn iter_all(&self) -> impl Iterator> { let mut prev_mxc = None; self.db @@ -206,7 +205,7 @@ impl Service { /// Generates a thumbnail from the given image file contents. Returns /// `Ok(None)` if the input image should be used as-is. - #[tracing::instrument( + #[t::instrument( skip(file), fields(input_size = file.len(), original_width, original_height), )] @@ -219,18 +218,18 @@ impl Service { let image = match image::load_from_memory(file) { Ok(image) => image, Err(error) => { - warn!(%error, "Failed to parse source image"); + t::warn!(%error, "Failed to parse source image"); return Ok(None); } }; let original_width = image.width(); let original_height = image.height(); - tracing::Span::current().record("original_width", original_width); - tracing::Span::current().record("original_height", original_height); + t::Span::current().record("original_width", original_width); + t::Span::current().record("original_height", original_height); if width > original_width || height > original_height { - debug!("Requested thumbnail is larger than source image"); + t::debug!("Requested thumbnail is larger than source image"); return Ok(None); } @@ -276,7 +275,7 @@ impl Service { image.thumbnail_exact(exact_width, exact_height) }; - debug!("Serializing thumbnail as PNG"); + t::debug!("Serializing thumbnail as PNG"); let mut thumbnail_bytes = Vec::new(); thumbnail.write_to( &mut Cursor::new(&mut thumbnail_bytes), @@ -299,7 +298,7 @@ impl Service { /// /// For width,height <= 96 the server uses another thumbnailing algorithm /// which crops the image afterwards. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn get_thumbnail( &self, mxc: OwnedMxcUri, @@ -313,26 +312,26 @@ impl Service { if let Some((meta, key)) = self.db.search_file_metadata(mxc.clone(), width, height)? { - debug!("Using saved thumbnail"); + t::debug!("Using saved thumbnail"); return Ok(self.read_content(&key).await?.map(|file| (meta, file))); } let Some((meta, key)) = self.db.search_file_metadata(mxc.clone(), 0, 0)? else { - debug!("Original image not found, can't generate thumbnail"); + t::debug!("Original image not found, can't generate thumbnail"); return Ok(None); }; let Some(file) = self.read_content(&key).await? else { - debug!("Original image not found, can't generate thumbnail"); + t::debug!("Original image not found, can't generate thumbnail"); return Ok(None); }; - debug!("Generating thumbnail"); + t::debug!("Generating thumbnail"); let thumbnail_result = { let file = file.clone(); - let outer_span = tracing::span::Span::current(); + let outer_span = t::span::Span::current(); tokio::task::spawn_blocking(move || { outer_span.in_scope(|| { @@ -344,11 +343,11 @@ impl Service { }; let Some(thumbnail_bytes) = thumbnail_result? else { - debug!("Returning source image as-is"); + t::debug!("Returning source image as-is"); return Ok(Some((meta, file))); }; - debug!("Saving created thumbnail"); + t::debug!("Saving created thumbnail"); // Save thumbnail in database so we don't have to generate it // again next time diff --git a/src/service/pdu.rs b/src/service/pdu.rs index b6052a4c..2eb4a048 100644 --- a/src/service/pdu.rs +++ b/src/service/pdu.rs @@ -22,9 +22,8 @@ use serde_json::{ json, value::{to_raw_value, RawValue as RawJsonValue}, }; -use tracing::warn; -use crate::Error; +use crate::{observability::prelude::*, Error}; /// Content hashes of a PDU. #[derive(Clone, Debug, Deserialize, Serialize)] @@ -60,7 +59,7 @@ pub(crate) struct PduEvent { } impl PduEvent { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn redact( &mut self, room_version_id: RoomVersionId, @@ -183,7 +182,7 @@ impl PduEvent { (self.redacts.clone(), self.content.clone()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_sync_room_event(&self) -> Raw { let (redacts, content) = self.copy_redacts(); let mut json = json!({ @@ -208,7 +207,7 @@ impl PduEvent { } /// This only works for events that are also AnyRoomEvents. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_any_event(&self) -> Raw { let mut json = json!({ "content": self.content, @@ -232,7 +231,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_room_event(&self) -> Raw { let (redacts, content) = self.copy_redacts(); let mut json = json!({ @@ -257,7 +256,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_message_like_event(&self) -> Raw { let (redacts, content) = self.copy_redacts(); let mut json = json!({ @@ -282,7 +281,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_state_event(&self) -> Raw { let mut json = json!({ "content": self.content, @@ -301,7 +300,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_sync_state_event(&self) -> Raw { let mut json = json!({ "content": self.content, @@ -319,7 +318,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_stripped_state_event(&self) -> Raw { let json = json!({ "content": self.content, @@ -331,7 +330,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_stripped_spacechild_state_event( &self, ) -> Raw { @@ -346,7 +345,7 @@ impl PduEvent { serde_json::from_value(json).expect("Raw::from_value always works") } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn to_member_event( &self, ) -> Raw> { @@ -369,7 +368,7 @@ impl PduEvent { } /// This does not return a full `Pdu` it is only to satisfy ruma's types. - #[tracing::instrument(skip(pdu_json))] + #[t::instrument(skip(pdu_json))] pub(crate) fn convert_to_outgoing_federation_event( mut pdu_json: CanonicalJsonObject, ) -> Box { @@ -475,7 +474,7 @@ pub(crate) fn gen_event_id_canonical_json( ) -> crate::Result<(OwnedEventId, CanonicalJsonObject)> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()).map_err(|error| { - warn!(%error, object = ?pdu, "Error parsing incoming event"); + t::warn!(%error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; diff --git a/src/service/pusher.rs b/src/service/pusher.rs index c2ae7c46..d132ea14 100644 --- a/src/service/pusher.rs +++ b/src/service/pusher.rs @@ -23,9 +23,10 @@ use ruma::{ serde::Raw, uint, RoomId, UInt, UserId, }; -use tracing::warn; -use crate::{services, utils, Error, PduEvent, Result}; +use crate::{ + observability::prelude::*, services, utils, Error, PduEvent, Result, +}; mod data; @@ -63,7 +64,7 @@ impl Service { self.db.get_pushkeys(sender) } - #[tracing::instrument(skip(self, destination, request))] + #[t::instrument(skip(self, destination, request))] pub(crate) async fn send_request( &self, destination: &str, @@ -81,7 +82,7 @@ impl Service { &[MatrixVersion::V1_0], ) .map_err(|error| { - warn!(%error, %destination, "Failed to find destination"); + t::warn!(%error, %destination, "Failed to find destination"); Error::BadServerResponse("Invalid destination") })? .map(BytesMut::freeze); @@ -108,12 +109,12 @@ impl Service { // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - warn!(%error, "Server error"); + t::warn!(%error, "Server error"); Vec::new().into() }); if status != 200 { - warn!( + t::warn!( push_gateway = %destination, %status, %url, @@ -131,7 +132,7 @@ impl Service { .expect("reqwest body is valid http body"), ); response.map_err(|error| { - warn!( + t::warn!( %error, appservice = %destination, %url, @@ -143,7 +144,7 @@ impl Service { }) } Err(error) => { - warn!( + t::warn!( %error, %destination, "Could not send request to push gateway", @@ -153,7 +154,7 @@ impl Service { } } - #[tracing::instrument(skip(self, user, unread, pusher, ruleset, pdu))] + #[t::instrument(skip(self, user, unread, pusher, ruleset, pdu))] pub(crate) async fn send_push_notice( &self, user: &UserId, @@ -210,7 +211,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, user, ruleset, pdu))] + #[t::instrument(skip(self, user, ruleset, pdu))] pub(crate) fn get_actions<'a>( &self, user: &UserId, @@ -240,7 +241,7 @@ impl Service { Ok(ruleset.get_actions(pdu, &ctx)) } - #[tracing::instrument(skip(self, unread, pusher, tweaks, event))] + #[t::instrument(skip(self, unread, pusher, tweaks, event))] async fn send_notice( &self, unread: UInt, diff --git a/src/service/rooms/auth_chain.rs b/src/service/rooms/auth_chain.rs index 3c8e4b38..0f54b312 100644 --- a/src/service/rooms/auth_chain.rs +++ b/src/service/rooms/auth_chain.rs @@ -5,11 +5,10 @@ use std::{ use lru_cache::LruCache; use ruma::{api::client::error::ErrorKind, EventId, RoomId}; -use tracing::{debug, error, warn}; use super::short::ShortEventId; use crate::{ - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, services, utils::debug_slice_truncated, Error, Result, @@ -66,7 +65,7 @@ impl Service { Ok(Some(chain)) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn cache_auth_chain( &self, key: Vec, @@ -79,7 +78,7 @@ impl Service { Ok(()) } - #[tracing::instrument( + #[t::instrument( skip(self, starting_events), fields(starting_events = debug_slice_truncated(&starting_events, 5)), )] @@ -146,7 +145,7 @@ impl Service { vec![sevent_id], Arc::clone(&auth_chain), )?; - debug!( + t::debug!( event_id = ?event_id, chain_length = ?auth_chain.len(), "Cache missed event" @@ -159,7 +158,7 @@ impl Service { } }; } - debug!( + t::debug!( chunk_cache_length = ?chunk_cache.len(), hits = ?hits2, misses = ?misses2, @@ -170,7 +169,7 @@ impl Service { full_auth_chain.extend(chunk_cache.iter()); } - debug!( + t::debug!( chain_length = ?full_auth_chain.len(), hits = ?hits, misses = ?misses, @@ -182,7 +181,7 @@ impl Service { })) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn get_auth_chain_inner( &self, room_id: &RoomId, @@ -195,7 +194,11 @@ impl Service { match services().rooms.timeline.get_pdu(&event_id) { Ok(Some(pdu)) => { if pdu.room_id != room_id { - warn!(bad_room_id = %pdu.room_id, "Event referenced in auth chain has incorrect room id"); + t::warn!( + bad_room_id = %pdu.room_id, + "Event referenced in auth chain has incorrect room \ + id" + ); return Err(Error::BadRequest( ErrorKind::forbidden(), "Event has incorrect room id", @@ -214,13 +217,13 @@ impl Service { } } Ok(None) => { - warn!( + t::warn!( ?event_id, "Could not find pdu mentioned in auth events" ); } Err(error) => { - error!( + t::error!( ?event_id, ?error, "Could not load event in auth chain" diff --git a/src/service/rooms/edus/typing.rs b/src/service/rooms/edus/typing.rs index 097fed27..94c874c9 100644 --- a/src/service/rooms/edus/typing.rs +++ b/src/service/rooms/edus/typing.rs @@ -5,9 +5,8 @@ use ruma::{ OwnedRoomId, OwnedUserId, RoomId, UserId, }; use tokio::sync::{broadcast, RwLock}; -use tracing::trace; -use crate::{services, utils, Result}; +use crate::{observability::prelude::*, services, utils, Result}; pub(crate) struct Service { // u64 is unix timestamp of timeout @@ -28,7 +27,7 @@ impl Service { /// Sets a user as typing until the timeout timestamp is reached or /// `roomtyping_remove` is called. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn typing_add( &self, user_id: &UserId, @@ -46,7 +45,7 @@ impl Service { .await .insert(room_id.to_owned(), services().globals.next_count()?); if self.typing_update_sender.send(room_id.to_owned()).is_err() { - trace!( + t::trace!( "receiver found what it was looking for and is no longer \ interested" ); @@ -55,7 +54,7 @@ impl Service { } /// Removes a user from typing before the timeout is reached. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn typing_remove( &self, user_id: &UserId, @@ -72,7 +71,7 @@ impl Service { .await .insert(room_id.to_owned(), services().globals.next_count()?); if self.typing_update_sender.send(room_id.to_owned()).is_err() { - trace!( + t::trace!( "receiver found what it was looking for and is no longer \ interested" ); @@ -80,7 +79,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn wait_for_update(&self, room_id: &RoomId) -> Result<()> { let mut receiver = self.typing_update_sender.subscribe(); while let Ok(next) = receiver.recv().await { @@ -93,7 +92,7 @@ impl Service { } /// Makes sure that typing events with old timestamps get removed. - #[tracing::instrument(skip(self, room_id))] + #[t::instrument(skip(self, room_id))] async fn typings_maintain(&self, room_id: &RoomId) -> Result<()> { let current_timestamp = utils::millis_since_unix_epoch(); let mut removable = Vec::new(); @@ -120,7 +119,7 @@ impl Service { .await .insert(room_id.to_owned(), services().globals.next_count()?); if self.typing_update_sender.send(room_id.to_owned()).is_err() { - trace!( + t::trace!( "receiver found what it was looking for and is no longer \ interested" ); @@ -130,7 +129,7 @@ impl Service { } /// Returns the count of the last typing update in this room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn last_typing_update( &self, room_id: &RoomId, @@ -146,7 +145,7 @@ impl Service { } /// Returns a new typing EDU. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn typings_all( &self, room_id: &RoomId, diff --git a/src/service/rooms/event_handler.rs b/src/service/rooms/event_handler.rs index 1543e423..12e0fcea 100644 --- a/src/service/rooms/event_handler.rs +++ b/src/service/rooms/event_handler.rs @@ -34,13 +34,13 @@ use ruma::{ use serde::Deserialize; use serde_json::value::RawValue as RawJsonValue; use tokio::sync::{RwLock, RwLockWriteGuard, Semaphore}; -use tracing::{debug, error, info, trace, warn}; use super::{ short::ShortStateKey, state_compressor::CompressedStateEvent, timeline::PduId, }; use crate::{ + observability::prelude::*, service::{globals::SigningKeys, pdu, rooms::state::ExtractVersion}, services, utils::{debug_slice_truncated, room_version::RoomVersion}, @@ -82,7 +82,7 @@ impl Service { /// 13. Use state resolution to find new room state /// 14. Check if the event passes auth based on the "current state" of the /// room, if not soft fail it - #[tracing::instrument(skip(self, value, is_timeline_event, pub_key_map))] + #[t::instrument(skip(self, value, is_timeline_event, pub_key_map))] pub(crate) async fn handle_incoming_pdu<'a>( &self, origin: &'a ServerName, @@ -160,7 +160,7 @@ impl Service { .await?; let mut errors = 0; - debug!(events = ?sorted_prev_events, "Got previous events"); + t::debug!(events = ?sorted_prev_events, "Got previous events"); for prev_id in sorted_prev_events { // Check for disabled again because it might have changed if services().rooms.metadata.is_disabled(room_id)? { @@ -186,7 +186,10 @@ impl Service { } if time.elapsed() < min_elapsed_duration { - info!(event_id = %prev_id, "Backing off from prev event"); + t::info!( + event_id = %prev_id, + "Backing off from prev event" + ); continue; } } @@ -239,7 +242,7 @@ impl Service { .await { errors += 1; - warn!(%error, event_id = %prev_id, "Prev event failed"); + t::warn!(%error, event_id = %prev_id, "Prev event failed"); match services() .globals .bad_event_ratelimiter @@ -261,7 +264,7 @@ impl Service { .write() .await .remove(&room_id.to_owned()); - debug!( + t::debug!( elapsed = ?start_time.elapsed(), event_id = %prev_id, "Finished handling prev event", @@ -299,7 +302,7 @@ impl Service { } #[allow(clippy::too_many_arguments)] - #[tracing::instrument(skip(self, origin, room_id, value, pub_key_map))] + #[t::instrument(skip(self, origin, room_id, value, pub_key_map))] fn handle_outlier_pdu<'a>( &'a self, origin: &'a ServerName, @@ -333,7 +336,7 @@ impl Service { let origin_server_ts = value.get("origin_server_ts").ok_or_else(|| { - error!("Invalid PDU, no origin_server_ts field"); + t::error!("Invalid PDU, no origin_server_ts field"); Error::BadRequest( ErrorKind::MissingParam, "Invalid PDU, no origin_server_ts field", @@ -377,7 +380,7 @@ impl Service { ) { Err(error) => { // Drop - warn!(%event_id, %error, "Dropping bad event"); + t::warn!(%event_id, %error, "Dropping bad event"); return Err(Error::BadRequest( ErrorKind::InvalidParam, "Signature verification failed", @@ -385,7 +388,7 @@ impl Service { } Ok(ruma::signatures::Verified::Signatures) => { // Redact - warn!(%event_id, "Calculated hash does not match"); + t::warn!(%event_id, "Calculated hash does not match"); let Ok(obj) = ruma::canonical_json::redact( value, room_version_id, @@ -440,7 +443,10 @@ impl Service { // to auth events" // NOTE: Step 5 is not applied anymore because it failed too // often - debug!(event_id = ?incoming_pdu.event_id, "Fetching auth events"); + t::debug!( + event_id = ?incoming_pdu.event_id, + "Fetching auth events" + ); self.fetch_and_handle_outliers( origin, &incoming_pdu @@ -457,7 +463,7 @@ impl Service { // 6. Reject "due to auth events" if the event doesn't pass auth // based on the auth events - debug!( + t::debug!( event_id = %incoming_pdu.event_id, "Starting auth check for event based on auth events", ); @@ -468,7 +474,7 @@ impl Service { let Some(auth_event) = services().rooms.timeline.get_pdu(event_id)? else { - warn!(%event_id, "Could not find auth event"); + t::warn!(%event_id, "Could not find auth event"); continue; }; @@ -521,7 +527,7 @@ impl Service { )); } - debug!("Validation successful"); + t::debug!("Validation successful"); // 7. Persist the event as an outlier. services() @@ -529,13 +535,13 @@ impl Service { .outlier .add_pdu_outlier(&incoming_pdu.event_id, &val)?; - debug!("Added pdu as outlier"); + t::debug!("Added pdu as outlier"); Ok((Arc::new(incoming_pdu), val)) }) } - #[tracing::instrument(skip_all, fields( + #[t::instrument(skip_all, fields( incoming_pdu = %incoming_pdu.event_id, ))] pub(crate) async fn upgrade_outlier_to_timeline_pdu( @@ -565,7 +571,7 @@ impl Service { )); } - debug!( + t::debug!( event_id = %incoming_pdu.event_id, "Upgrading event to timeline pdu", ); @@ -584,7 +590,7 @@ impl Service { // the request and build the state from a known point and // resolve if > 1 prev_event - debug!("Requesting state at event"); + t::debug!("Requesting state at event"); let mut state_at_incoming_event = None; if incoming_pdu.prev_events.len() == 1 { @@ -607,7 +613,7 @@ impl Service { }; if let Some(Ok(mut state)) = state { - debug!("Using cached state"); + t::debug!("Using cached state"); let prev_pdu = services() .rooms .timeline @@ -634,7 +640,7 @@ impl Service { state_at_incoming_event = Some(state); } } else { - debug!("Calculating state at event using state res"); + t::debug!("Calculating state at event using state res"); let mut extremity_sstatehashes = HashMap::new(); let mut okay = true; @@ -701,7 +707,7 @@ impl Service { id.clone(), ); } else { - warn!("Failed to get_statekey_from_short"); + t::warn!("Failed to get_statekey_from_short"); } starting_events.push(id); } @@ -727,7 +733,10 @@ impl Service { |event_id| { let res = services().rooms.timeline.get_pdu(event_id); if let Err(error) = &res { - error!(%error, %event_id, "Failed to fetch event"); + t::error!( + %error, + %event_id, "Failed to fetch event" + ); } res.ok().flatten() }, @@ -751,7 +760,7 @@ impl Service { .collect::>()?, ), Err(error) => { - warn!( + t::warn!( %error, "State resolution on prev events failed, either \ an event could not be found or deserialization" @@ -763,7 +772,7 @@ impl Service { } if state_at_incoming_event.is_none() { - debug!("Calling /state_ids"); + t::debug!("Calling /state_ids"); // Call /state_ids to find out what the state at this pdu is. We // trust the server's response to some extend, but we // still do a lot of checks on the events @@ -779,7 +788,7 @@ impl Service { .await { Ok(res) => { - debug!("Fetching state events at event"); + t::debug!("Fetching state events at event"); let collect = res .pdu_ids .iter() @@ -863,7 +872,7 @@ impl Service { state_at_incoming_event = Some(state); } Err(error) => { - warn!(%error, "Fetching state for event failed"); + t::warn!(%error, "Fetching state for event failed"); return Err(error); } }; @@ -872,7 +881,7 @@ impl Service { let state_at_incoming_event = state_at_incoming_event.expect("we always set this to some above"); - debug!("Starting auth check"); + t::debug!("Starting auth check"); // 11. Check the auth of the event passes based on the state of the // event let check_result = state_res::event_auth::auth_check( @@ -909,7 +918,7 @@ impl Service { "Event has failed auth check with state at the event.", )); } - debug!("Auth check succeeded"); + t::debug!("Auth check succeeded"); // Soft fail check before doing state res let auth_events = services().rooms.state.get_auth_events( @@ -972,7 +981,7 @@ impl Service { // Now we calculate the set of extremities this room has after the // incoming event has been applied. We start with the previous // extremities (aka leaves) - debug!("Calculating extremities"); + t::debug!("Calculating extremities"); let mut extremities = services().rooms.state.get_forward_extremities(room_id)?; @@ -992,7 +1001,7 @@ impl Service { ) }); - debug!("Compressing state at event"); + t::debug!("Compressing state at event"); let state_ids_compressed = Arc::new( state_at_incoming_event .iter() @@ -1006,7 +1015,7 @@ impl Service { ); if incoming_pdu.state_key.is_some() { - debug!("Preparing for stateres to derive new room state"); + t::debug!("Preparing for stateres to derive new room state"); // We also add state after incoming event to the fork states let mut state_after = state_at_incoming_event.clone(); @@ -1026,7 +1035,7 @@ impl Service { .await?; // Set the new room state to the resolved state - debug!("Forcing new room state"); + t::debug!("Forcing new room state"); let (sstatehash, new, removed) = services() .rooms @@ -1042,7 +1051,7 @@ impl Service { // 14. Check if the event passes auth based on the "current state" of // the room, if not soft fail it - debug!("Starting soft fail auth check"); + t::debug!("Starting soft fail auth check"); if soft_fail { services() @@ -1060,7 +1069,7 @@ impl Service { // Soft fail, we keep the event as an outlier but don't add it to // the timeline - warn!("Event was soft failed"); + t::warn!("Event was soft failed"); services() .rooms .pdu_metadata @@ -1071,7 +1080,7 @@ impl Service { )); } - debug!("Appending pdu to timeline"); + t::debug!("Appending pdu to timeline"); extremities.insert(incoming_pdu.event_id.clone()); // Now that the event has passed all auth it is added into the timeline. @@ -1091,21 +1100,21 @@ impl Service { ) .await?; - debug!("Appended incoming pdu"); + t::debug!("Appended incoming pdu"); // Event has passed all auth/stateres checks drop(room_token); Ok(pdu_id) } - #[tracing::instrument(skip(self, room_version_id, incoming_state))] + #[t::instrument(skip(self, room_version_id, incoming_state))] async fn resolve_state( &self, room_id: &RoomId, room_version_id: &RoomVersionId, incoming_state: HashMap>, ) -> Result>> { - debug!("Loading current room state ids"); + t::debug!("Loading current room state ids"); let current_sstatehash = services() .rooms .state @@ -1135,7 +1144,7 @@ impl Service { ); } - debug!("Loading fork states"); + t::debug!("Loading fork states"); let fork_states: Vec<_> = fork_states .into_iter() @@ -1155,12 +1164,12 @@ impl Service { }) .collect(); - debug!("Resolving state"); + t::debug!("Resolving state"); let fetch_event = |id: &_| { let res = services().rooms.timeline.get_pdu(id); if let Err(error) = &res { - error!(%error, "Failed to fetch event"); + t::error!(%error, "Failed to fetch event"); } res.ok().flatten() }; @@ -1180,7 +1189,7 @@ impl Service { drop(lock); - debug!("State resolution done; compressing state"); + t::debug!("State resolution done; compressing state"); let new_room_state = state .into_iter() @@ -1209,7 +1218,7 @@ impl Service { /// b. Look at outlier pdu tree /// c. Ask origin server over federation /// d. TODO: Ask other servers over federation? - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) fn fetch_and_handle_outliers<'a>( &'a self, origin: &'a ServerName, @@ -1244,7 +1253,7 @@ impl Service { if let Ok(Some(local_pdu)) = services().rooms.timeline.get_pdu(event_id) { - trace!(%event_id, "Found event locally"); + t::trace!(%event_id, "Found event locally"); pdus.push((local_pdu, None)); continue; } @@ -1275,7 +1284,7 @@ impl Service { } if time.elapsed() < min_elapsed_duration { - info!( + t::info!( event_id = %next_id, "Backing off from event", ); @@ -1295,11 +1304,11 @@ impl Service { if let Ok(Some(_)) = services().rooms.timeline.get_pdu(&next_id) { - trace!(event_id = %next_id, "Found event locally"); + t::trace!(event_id = %next_id, "Found event locally"); continue; } - info!( + t::info!( event_id = %next_id, "Fetching event over federation", ); @@ -1313,7 +1322,10 @@ impl Service { ) .await { - info!(event_id = %next_id, "Got event over federation"); + t::info!( + event_id = %next_id, + "Got event over federation" + ); let Ok((calculated_event_id, value)) = pdu::gen_event_id_canonical_json( &res.pdu, @@ -1325,7 +1337,7 @@ impl Service { }; if calculated_event_id != *next_id { - warn!( + t::warn!( expected_event_id = %next_id, actual_event_id = %calculated_event_id, "Server returned an event with a different ID \ @@ -1343,17 +1355,17 @@ impl Service { let a: Arc = auth_event; todo_auth_events.push(a); } else { - warn!("Auth event id is not valid"); + t::warn!("Auth event id is not valid"); } } } else { - warn!("Auth event list invalid"); + t::warn!("Auth event list invalid"); } events_in_reverse_order.push((next_id.clone(), value)); events_all.insert(next_id); } else { - warn!(event_id = %next_id, "Failed to fetch event"); + t::warn!(event_id = %next_id, "Failed to fetch event"); back_off((*next_id).to_owned()).await; } } @@ -1377,7 +1389,7 @@ impl Service { } if time.elapsed() < min_elapsed_duration { - info!( + t::info!( event_id = %next_id, "Backing off from event", ); @@ -1403,7 +1415,7 @@ impl Service { } } Err(error) => { - warn!( + t::warn!( event_id = %next_id, %error, "Event failed auth checks", @@ -1417,7 +1429,7 @@ impl Service { }) } - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] #[allow(clippy::type_complexity)] async fn fetch_unknown_prev_events( &self, @@ -1457,7 +1469,7 @@ impl Service { if amount > services().globals.max_fetch_prev_events() { // Max limit reached - warn!("Max prev event limit reached!"); + t::warn!("Max prev event limit reached!"); graph.insert(prev_event_id.clone(), HashSet::new()); continue; } @@ -1519,7 +1531,7 @@ impl Service { Ok((sorted, eventid_info)) } - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) async fn fetch_required_signing_keys( &self, event: &CanonicalJsonObject, @@ -1560,7 +1572,7 @@ impl Service { .await; let Ok(keys) = fetch_res else { - warn!("Failed to fetch signing key"); + t::warn!("Failed to fetch signing key"); continue; }; @@ -1573,7 +1585,7 @@ impl Service { // Gets a list of servers for which we don't have the signing key yet. We go // over the PDUs and either cache the key or add it to the list that // needs to be retrieved. - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] async fn get_server_keys_from_cache( &self, pdu: &RawJsonValue, @@ -1586,7 +1598,7 @@ impl Service { ) -> Result<()> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - error!(%error, ?pdu, "Invalid PDU in server response"); + t::error!(%error, ?pdu, "Invalid PDU in server response"); Error::BadServerResponse("Invalid PDU in server response") })?; @@ -1618,7 +1630,7 @@ impl Service { } if time.elapsed() < min_elapsed_duration { - debug!(%event_id, "Backing off from event"); + t::debug!(%event_id, "Backing off from event"); return Err(Error::BadServerResponse( "Bad event, still backing off", )); @@ -1674,11 +1686,14 @@ impl Service { continue; } - trace!(server = %origin, "Loading signing keys for other server"); + t::trace!( + server = %origin, + "Loading signing keys for other server" + ); let result = services().globals.signing_keys_for(origin)?; if !result.as_ref().is_some_and(contains_all_ids) { - trace!( + t::trace!( server = %origin, "Signing key not loaded for server", ); @@ -1724,7 +1739,7 @@ impl Service { ) .await { - debug!(%error, "Failed to get server keys from cache"); + t::debug!(%error, "Failed to get server keys from cache"); }; } @@ -1732,12 +1747,12 @@ impl Service { }; if servers.is_empty() { - info!("We had all keys locally"); + t::info!("We had all keys locally"); return Ok(()); } for server in services().globals.trusted_servers() { - info!(%server, "Asking batch signing keys from trusted server"); + t::info!(%server, "Asking batch signing keys from trusted server"); if let Ok(keys) = services() .sending .send_federation_request( @@ -1748,13 +1763,13 @@ impl Service { ) .await { - trace!(signing_keys = ?keys, "Got signing keys"); + t::trace!(signing_keys = ?keys, "Got signing keys"); let mut pkm = pub_key_map.write().await; for k in keys.server_keys { let k = match k.deserialize() { Ok(key) => key, Err(error) => { - warn!( + t::warn!( %error, %server, object = ?k.json(), @@ -1779,12 +1794,12 @@ impl Service { } if servers.is_empty() { - info!("Trusted server supplied all signing keys"); + t::info!("Trusted server supplied all signing keys"); return Ok(()); } } - info!(?servers, "Asking individual servers for signing keys"); + t::info!(?servers, "Asking individual servers for signing keys"); let mut futures: FuturesUnordered<_> = servers .into_keys() .map(|server| async move { @@ -1803,7 +1818,7 @@ impl Service { while let Some(result) = futures.next().await { if let (Ok(get_keys_response), origin) = result { - info!(server = %origin, "Received new result from server"); + t::info!(server = %origin, "Received new result from server"); if let Ok(key) = get_keys_response.server_key.deserialize() { let result = services() .globals @@ -1814,10 +1829,10 @@ impl Service { .insert(origin.to_string(), result); } } - info!("Done handling result"); + t::info!("Done handling result"); } - info!("Search for signing keys done"); + t::info!("Search for signing keys done"); Ok(()) } @@ -1825,7 +1840,7 @@ impl Service { /// Returns Ok if the acl allows the server // Allowed because this function uses `services()` #[allow(clippy::unused_self)] - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) fn acl_check( &self, server_name: &ServerName, @@ -1846,7 +1861,7 @@ impl Service { { Ok(x) => x, Err(error) => { - warn!(%error, "Invalid ACL event"); + t::warn!(%error, "Invalid ACL event"); return Ok(()); } }; @@ -1859,7 +1874,7 @@ impl Service { if acl_event_content.is_allowed(server_name) { Ok(()) } else { - info!( + t::info!( server = %server_name, %room_id, "Other server was denied by room ACL", @@ -1873,7 +1888,7 @@ impl Service { /// Search the DB for the signing keys of the given server, if we don't have /// them fetch them from the server and save to our DB. - #[tracing::instrument( + #[t::instrument( skip(self, signature_ids), fields(signature_ids = debug_slice_truncated(&signature_ids, 3)) )] @@ -1899,7 +1914,7 @@ impl Service { .any(|key_id| id == &key_id); if !in_verify_keys && !in_old_verify_keys { - trace!(id, "signature key not yet in known set"); + t::trace!(id, "signature key not yet in known set"); return false; } } @@ -1945,14 +1960,14 @@ impl Service { } if time.elapsed() < min_elapsed_duration { - debug!(?signature_ids, "Backing off from signatures"); + t::debug!(?signature_ids, "Backing off from signatures"); return Err(Error::BadServerResponse( "bad signature, still backing off", )); } } - trace!("Loading signing keys from database"); + t::trace!("Loading signing keys from database"); let result = services().globals.signing_keys_for(origin)?; @@ -1964,7 +1979,7 @@ impl Service { ) .expect("Should be valid until year 500,000,000"); - debug!( + t::debug!( server = %origin, key_ids = ?result.verify_keys.keys().collect::>(), old_key_ids = @@ -1978,7 +1993,7 @@ impl Service { // We want to ensure that the keys remain valid by the time the // other functions that handle signatures reach them if result.valid_until_ts > ts_threshold { - debug!( + t::debug!( origin = %origin, valid_until_ts = %result.valid_until_ts.get(), "Keys are valid because they expire after threshold", @@ -1987,7 +2002,7 @@ impl Service { } expires_soon_or_has_expired = true; - trace!("Found all keys, but they will expire too soon"); + t::trace!("Found all keys, but they will expire too soon"); } } @@ -2004,7 +2019,7 @@ impl Service { ) .expect("Should be valid until year 500,000,000"); - debug!("Fetching signing keys over federation"); + t::debug!("Fetching signing keys over federation"); if let Some(mut server_key) = services() .sending @@ -2052,7 +2067,7 @@ impl Service { if query_via_trusted_servers { for server in services().globals.trusted_servers() { - debug!( + t::debug!( trusted_server = %server, origin = %origin, "Asking trusted server for signing keys", @@ -2080,7 +2095,7 @@ impl Service { .collect::>() }) { - trace!( + t::trace!( ?server_keys, "Got signing keys from trusted server" ); @@ -2129,7 +2144,7 @@ impl Service { .map(|(id, key)| (id.to_string(), key)), ); } else { - warn!( + t::warn!( origin = %origin, valid_until = %k.valid_until_ts.get(), "Server gave us keys older than we \ @@ -2147,7 +2162,7 @@ impl Service { // We should return these keys if fresher keys were not found if expires_soon_or_has_expired { - info!(origin = %origin, "Returning stale keys"); + t::info!(origin = %origin, "Returning stale keys"); return Ok(keys); } @@ -2155,14 +2170,14 @@ impl Service { back_off(signature_ids).await; - warn!("Failed to find all public keys"); + t::warn!("Failed to find all public keys"); Err(Error::BadServerResponse("Failed to find public key for server")) } - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] fn check_room_id(room_id: &RoomId, pdu: &PduEvent) -> Result<()> { if pdu.room_id != room_id { - warn!( + t::warn!( event_id = %pdu.event_id, expected_room_id = %pdu.room_id, actual_room_id = %room_id, diff --git a/src/service/rooms/lazy_loading.rs b/src/service/rooms/lazy_loading.rs index 4c0508f1..17d8c51b 100644 --- a/src/service/rooms/lazy_loading.rs +++ b/src/service/rooms/lazy_loading.rs @@ -4,7 +4,7 @@ use ruma::{DeviceId, OwnedDeviceId, OwnedRoomId, OwnedUserId, RoomId, UserId}; use tokio::sync::Mutex; use super::timeline::PduCount; -use crate::Result; +use crate::{observability::prelude::*, Result}; mod data; @@ -30,7 +30,7 @@ impl Service { } } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn lazy_load_was_sent_before( &self, user_id: &UserId, @@ -41,7 +41,7 @@ impl Service { self.db.lazy_load_was_sent_before(user_id, device_id, room_id, ll_user) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn lazy_load_mark_sent( &self, user_id: &UserId, @@ -61,7 +61,7 @@ impl Service { ); } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn lazy_load_confirm_delivery( &self, user_id: &UserId, @@ -86,7 +86,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn lazy_load_reset( &self, user_id: &UserId, diff --git a/src/service/rooms/pdu_metadata.rs b/src/service/rooms/pdu_metadata.rs index d3854523..8d0025a3 100644 --- a/src/service/rooms/pdu_metadata.rs +++ b/src/service/rooms/pdu_metadata.rs @@ -8,7 +8,7 @@ use ruma::{ use serde::Deserialize; use super::timeline::PduCount; -use crate::{services, PduEvent, Result}; +use crate::{observability::prelude::*, services, PduEvent, Result}; mod data; @@ -29,7 +29,7 @@ struct ExtractRelatesToEventId { } impl Service { - #[tracing::instrument(skip(self, from, to))] + #[t::instrument(skip(self, from, to))] pub(crate) fn add_relation( &self, from: PduCount, @@ -48,7 +48,7 @@ impl Service { } #[allow(clippy::too_many_arguments, clippy::too_many_lines)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn paginate_relations_with_filter( &self, sender_user: &UserId, @@ -176,7 +176,7 @@ impl Service { } } - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) fn relations_until<'a>( &'a self, user_id: &'a UserId, @@ -195,7 +195,7 @@ impl Service { self.db.relations_until(user_id, room_id, target, until) } - #[tracing::instrument(skip(self, room_id, event_ids))] + #[t::instrument(skip(self, room_id, event_ids))] pub(crate) fn mark_as_referenced( &self, room_id: &RoomId, @@ -204,7 +204,7 @@ impl Service { self.db.mark_as_referenced(room_id, event_ids) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn is_event_referenced( &self, room_id: &RoomId, @@ -213,7 +213,7 @@ impl Service { self.db.is_event_referenced(room_id, event_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn mark_event_soft_failed( &self, event_id: &EventId, @@ -221,7 +221,7 @@ impl Service { self.db.mark_event_soft_failed(event_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn is_event_soft_failed( &self, event_id: &EventId, diff --git a/src/service/rooms/spaces.rs b/src/service/rooms/spaces.rs index bfcbb072..16ad90e8 100644 --- a/src/service/rooms/spaces.rs +++ b/src/service/rooms/spaces.rs @@ -29,10 +29,9 @@ use ruma::{ OwnedRoomId, RoomId, UserId, }; use tokio::sync::Mutex; -use tracing::{debug, error, warn}; use super::state::ExtractType; -use crate::{services, Error, PduEvent, Result}; +use crate::{observability::prelude::*, services, Error, PduEvent, Result}; pub(crate) enum CachedJoinRule { Full(JoinRule), @@ -59,7 +58,7 @@ impl Service { } #[allow(clippy::too_many_lines)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn get_hierarchy( &self, sender_user: &UserId, @@ -185,7 +184,7 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomJoinRulesEventContent| c.join_rule) .map_err(|error| { - error!( + t::error!( %error, "Invalid room join rule event" ); @@ -224,7 +223,7 @@ impl Service { // Early return so the client can see some data already break; } - debug!(%server, "Asking other server for /hierarchy"); + t::debug!(%server, "Asking other server for /hierarchy"); if let Ok(response) = services() .sending .send_federation_request( @@ -236,7 +235,7 @@ impl Service { ) .await { - warn!( + t::warn!( %server, ?response, "Got response from other server for /hierarchy", @@ -333,7 +332,7 @@ impl Service { } #[allow(clippy::too_many_lines)] - #[tracing::instrument(skip(self, children))] + #[t::instrument(skip(self, children))] fn get_room_chunk( &self, sender_user: &UserId, @@ -353,7 +352,7 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomCanonicalAliasEventContent| c.alias) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room canonical alias event" @@ -369,7 +368,7 @@ impl Service { .state_cache .room_joined_count(room_id)? .unwrap_or_else(|| { - warn!("Room has no member count"); + t::warn!("Room has no member count"); 0 }) .try_into() @@ -383,7 +382,7 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomTopicEventContent| Some(c.topic)) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room topic event" @@ -408,7 +407,7 @@ impl Service { == HistoryVisibility::WorldReadable }) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room history visibility event" @@ -429,7 +428,7 @@ impl Service { c.guest_access == GuestAccess::CanJoin }) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room guest access event" @@ -447,7 +446,7 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomAvatarEventContent| c.url) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room avatar event" @@ -472,7 +471,7 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomJoinRulesEventContent| c.join_rule) .map_err(|error| { - error!( + t::error!( %error, event_id = %s.event_id, "Invalid room join rule event", @@ -486,7 +485,7 @@ impl Service { .unwrap_or(JoinRule::Invite); if !self.handle_join_rule(&join_rule, sender_user, room_id)? { - debug!("User is not allowed to see room"); + t::debug!("User is not allowed to see room"); // This error will be caught later return Err(Error::BadRequest( ErrorKind::forbidden(), @@ -547,7 +546,7 @@ impl Service { Ok(allowed) } - #[tracing::instrument(skip(self, sender_user))] + #[t::instrument(skip(self, sender_user))] fn handle_join_rule( &self, join_rule: &JoinRule, diff --git a/src/service/rooms/state.rs b/src/service/rooms/state.rs index 5db98287..cc8a5889 100644 --- a/src/service/rooms/state.rs +++ b/src/service/rooms/state.rs @@ -16,10 +16,10 @@ use ruma::{ EventId, OwnedEventId, OwnedRoomId, RoomId, RoomVersionId, UserId, }; use serde::{de::DeserializeOwned, Deserialize}; -use tracing::warn; use super::{short::ShortStateHash, state_compressor::CompressedStateEvent}; use crate::{ + observability::prelude::*, service::globals::marker, services, utils::{ @@ -86,7 +86,7 @@ pub(crate) struct Service { impl Service { /// Set the room to the given statehash and update caches. - #[tracing::instrument(skip(self, statediffnew, _statediffremoved))] + #[t::instrument(skip(self, statediffnew, _statediffremoved))] pub(crate) async fn force_state( &self, room_id: &KeyToken, @@ -170,7 +170,7 @@ impl Service { /// /// This adds all current state events (not including the incoming event) /// to `stateid_pduid` and adds the incoming event to `eventid_statehash`. - #[tracing::instrument(skip(self, state_ids_compressed))] + #[t::instrument(skip(self, state_ids_compressed))] pub(crate) fn set_event_state( &self, event_id: &EventId, @@ -237,7 +237,7 @@ impl Service { /// /// This adds all current state events (not including the incoming event) /// to `stateid_pduid` and adds the incoming event to `eventid_statehash`. - #[tracing::instrument(skip(self, new_pdu))] + #[t::instrument(skip(self, new_pdu))] pub(crate) fn append_to_state( &self, new_pdu: &PduEvent, @@ -319,7 +319,7 @@ impl Service { /// Gather events to help the invited user identify the room /// /// Also includes the invite event itself. - #[tracing::instrument(skip(self, invite_event))] + #[t::instrument(skip(self, invite_event))] pub(crate) fn get_helpful_invite_events( &self, invite_event: &PduEvent, @@ -355,7 +355,7 @@ impl Service { } /// Set the state hash to a new version, but does not update state_cache. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn set_room_state( &self, room_id: &KeyToken, @@ -365,7 +365,7 @@ impl Service { } /// Returns the value of a field of an `m.room.create` event's `content`. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_create_content( &self, room_id: &RoomId, @@ -381,7 +381,7 @@ impl Service { .map(|create_event| { serde_json::from_str::(create_event.content.get()).map_err( |error| { - warn!(%error, "Invalid create event"); + t::warn!(%error, "Invalid create event"); Error::BadDatabase("Invalid create event in db.") }, ) @@ -397,7 +397,7 @@ impl Service { Ok(content_field.extract()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_room_shortstatehash( &self, room_id: &RoomId, @@ -405,7 +405,7 @@ impl Service { self.db.get_room_shortstatehash(room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_forward_extremities( &self, room_id: &RoomId, @@ -413,7 +413,7 @@ impl Service { self.db.get_forward_extremities(room_id) } - #[tracing::instrument( + #[t::instrument( skip(self, event_ids), fields(event_ids = debug_slice_truncated(&event_ids, 5)), )] @@ -426,7 +426,7 @@ impl Service { } /// This fetches auth events from the current state. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_auth_events( &self, room_id: &RoomId, diff --git a/src/service/rooms/state_accessor.rs b/src/service/rooms/state_accessor.rs index e9794e53..6616e361 100644 --- a/src/service/rooms/state_accessor.rs +++ b/src/service/rooms/state_accessor.rs @@ -22,11 +22,10 @@ use ruma::{ ServerName, UserId, }; use serde_json::value::to_raw_value; -use tracing::{error, warn}; use super::short::{ShortStateHash, ShortStateKey}; use crate::{ - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, service::{globals::marker, pdu::PduBuilder}, services, utils::on_demand_hashmap::KeyToken, @@ -63,7 +62,7 @@ impl Service { /// Builds a StateMap by iterating over all keys that start /// with state_hash, this gives the full state for the given state_hash. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn state_full_ids( &self, shortstatehash: ShortStateHash, @@ -92,7 +91,7 @@ impl Service { Ok(result) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn state_full( &self, shortstatehash: ShortStateHash, @@ -140,7 +139,7 @@ impl Service { /// Returns a single PDU from `room_id` with key (`event_type`, /// `state_key`). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn state_get_id( &self, shortstatehash: ShortStateHash, @@ -174,7 +173,7 @@ impl Service { /// Returns a single PDU from `room_id` with key (`event_type`, /// `state_key`). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn state_get( &self, shortstatehash: ShortStateHash, @@ -188,7 +187,7 @@ impl Service { } /// Get membership for given user in state - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn user_membership( &self, shortstatehash: ShortStateHash, @@ -211,7 +210,7 @@ impl Service { } /// The user was a joined member at this state (potentially in the past) - #[tracing::instrument(skip(self), ret(level = "trace"))] + #[t::instrument(skip(self), ret(level = "trace"))] fn user_was_joined( &self, shortstatehash: ShortStateHash, @@ -223,7 +222,7 @@ impl Service { /// The user was an invited or joined room member at this state (potentially /// in the past) - #[tracing::instrument(skip(self), ret(level = "trace"))] + #[t::instrument(skip(self), ret(level = "trace"))] fn user_was_invited( &self, shortstatehash: ShortStateHash, @@ -236,7 +235,7 @@ impl Service { /// Whether a server is allowed to see an event through federation, based on /// the room's history_visibility at that event's state. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn server_can_see_event( &self, origin: &ServerName, @@ -302,7 +301,7 @@ impl Service { .any(|member| self.user_was_joined(shortstatehash, &member)) } other => { - error!(kind = %other, "Unknown history visibility"); + t::error!(kind = %other, "Unknown history visibility"); false } }; @@ -321,7 +320,7 @@ impl Service { /// Whether a user is allowed to see an event, based on /// the room's history_visibility at that event's state. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn user_can_see_event( &self, user_id: &UserId, @@ -379,7 +378,7 @@ impl Service { self.user_was_joined(shortstatehash, user_id) } other => { - error!(kind = %other, "Unknown history visibility"); + t::error!(kind = %other, "Unknown history visibility"); false } }; @@ -398,7 +397,7 @@ impl Service { /// Whether a user is allowed to see an event, based on /// the room's history_visibility at that event's state. - #[tracing::instrument(skip(self, user_id, room_id))] + #[t::instrument(skip(self, user_id, room_id))] pub(crate) fn user_can_see_state_events( &self, user_id: &UserId, @@ -430,7 +429,7 @@ impl Service { } /// Returns the state hash for this pdu. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn pdu_shortstatehash( &self, event_id: &EventId, @@ -439,7 +438,7 @@ impl Service { } /// Returns the full room state. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn room_state_full( &self, room_id: &RoomId, @@ -455,7 +454,7 @@ impl Service { /// Returns a single PDU from `room_id` with key (`event_type`, /// `state_key`). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_state_get_id( &self, room_id: &RoomId, @@ -473,7 +472,7 @@ impl Service { /// Returns a single PDU from `room_id` with key (`event_type`, /// `state_key`). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_state_get( &self, room_id: &RoomId, @@ -489,7 +488,7 @@ impl Service { } } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_name(&self, room_id: &RoomId) -> Result> { self.room_state_get(room_id, &StateEventType::RoomName, "")?.map_or( Ok(None), @@ -497,7 +496,10 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomNameEventContent| Some(c.name)) .map_err(|error| { - error!(%error, "Invalid room name event in database"); + t::error!( + %error, + "Invalid room name event in database" + ); Error::BadDatabase( "Invalid room name event in database.", ) @@ -506,7 +508,7 @@ impl Service { ) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_avatar( &self, room_id: &RoomId, @@ -525,7 +527,7 @@ impl Service { // Allowed because this function uses `services()` #[allow(clippy::unused_self)] - #[tracing::instrument(skip(self), ret(level = "trace"))] + #[t::instrument(skip(self), ret(level = "trace"))] pub(crate) fn user_can_invite( &self, room_id: &KeyToken, @@ -551,7 +553,7 @@ impl Service { .is_ok() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_member( &self, room_id: &RoomId, @@ -574,7 +576,7 @@ impl Service { /// If `federation` is `true`, it allows redaction events from any user of /// the same server as the original event sender, [as required by room /// versions >= v3](https://spec.matrix.org/v1.10/rooms/v11/#handling-redactions) - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn user_can_redact( &self, redacts: &EventId, diff --git a/src/service/rooms/state_cache.rs b/src/service/rooms/state_cache.rs index ea6721d9..69797a76 100644 --- a/src/service/rooms/state_cache.rs +++ b/src/service/rooms/state_cache.rs @@ -12,10 +12,9 @@ use ruma::{ serde::Raw, OwnedRoomId, OwnedServerName, OwnedUserId, RoomId, ServerName, UserId, }; -use tracing::warn; use crate::{ - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, service::appservice::RegistrationInfo, services, Error, Result, }; @@ -46,7 +45,7 @@ impl Service { } /// Update current membership data. - #[tracing::instrument(skip(self, last_state))] + #[t::instrument(skip(self, last_state))] pub(crate) fn update_membership( &self, room_id: &RoomId, @@ -76,7 +75,7 @@ impl Service { .state .get_create_content::(room_id) .inspect_err(|error| { - warn!(%error, "Failed to get room predecessor"); + t::warn!(%error, "Failed to get room predecessor"); }) .ok() .flatten() @@ -111,7 +110,7 @@ impl Service { event.get(), ) .map_err(|error| { - warn!( + t::warn!( %error, %event_kind, "Invalid account data event", @@ -151,7 +150,7 @@ impl Service { /// joining an upgraded room. /// /// References to the predecessor room are not removed. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] fn copy_upgraded_account_data( &self, user_id: &UserId, @@ -216,7 +215,10 @@ impl Service { RoomAccountDataEventType::Tag, &event, ) { - warn!(%error, "error writing m.tag account data to upgraded room"); + t::warn!( + %error, + "error writing m.tag account data to upgraded room" + ); } Ok(()) @@ -291,13 +293,17 @@ impl Service { event_kind.clone(), &event, ) { - warn!(%event_kind, %error, "error writing account data event after upgrading room"); + t::warn!( + %event_kind, + %error, + "error writing account data event after upgrading room" + ); } } Ok(()) } - #[tracing::instrument(skip(self, room_id))] + #[t::instrument(skip(self, room_id))] pub(crate) fn update_joined_count( &self, room_id: &RoomId, @@ -313,7 +319,7 @@ impl Service { Ok(our_real_users) } - #[tracing::instrument(skip(self, room_id))] + #[t::instrument(skip(self, room_id))] pub(crate) fn get_our_real_users( &self, room_id: &RoomId, @@ -334,7 +340,7 @@ impl Service { Ok(our_real_users) } - #[tracing::instrument(skip(self, room_id, appservice))] + #[t::instrument(skip(self, room_id, appservice))] pub(crate) fn appservice_in_room( &self, room_id: &RoomId, @@ -368,7 +374,7 @@ impl Service { } /// Makes a user forget a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn forget( &self, room_id: &RoomId, @@ -378,7 +384,7 @@ impl Service { } /// Returns an iterator of all servers participating in this room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_servers<'a>( &'a self, room_id: &RoomId, @@ -386,7 +392,7 @@ impl Service { self.db.room_servers(room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn server_in_room( &self, server: &ServerName, @@ -397,7 +403,7 @@ impl Service { /// Returns an iterator of all rooms a server participates in (as far as we /// know). - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn server_rooms<'a>( &'a self, server: &ServerName, @@ -406,7 +412,7 @@ impl Service { } /// Returns an iterator over all joined members of a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_members<'a>( &'a self, room_id: &RoomId, @@ -414,7 +420,7 @@ impl Service { self.db.room_members(room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_joined_count( &self, room_id: &RoomId, @@ -422,7 +428,7 @@ impl Service { self.db.room_joined_count(room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_invited_count( &self, room_id: &RoomId, @@ -431,7 +437,7 @@ impl Service { } /// Returns an iterator over all invited members of a room. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn room_members_invited<'a>( &'a self, room_id: &RoomId, @@ -439,7 +445,7 @@ impl Service { self.db.room_members_invited(room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_invite_count( &self, room_id: &RoomId, @@ -448,7 +454,7 @@ impl Service { self.db.get_invite_count(room_id, user_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_left_count( &self, room_id: &RoomId, @@ -458,7 +464,7 @@ impl Service { } /// Returns an iterator over all rooms this user joined. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn rooms_joined<'a>( &'a self, user_id: &UserId, @@ -467,7 +473,7 @@ impl Service { } /// Returns an iterator over all rooms a user was invited to. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn rooms_invited<'a>( &'a self, user_id: &UserId, @@ -477,7 +483,7 @@ impl Service { self.db.rooms_invited(user_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn invite_state( &self, user_id: &UserId, @@ -486,7 +492,7 @@ impl Service { self.db.invite_state(user_id, room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn left_state( &self, user_id: &UserId, @@ -496,7 +502,7 @@ impl Service { } /// Returns an iterator over all rooms a user left. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn rooms_left<'a>( &'a self, user_id: &UserId, @@ -504,7 +510,7 @@ impl Service { self.db.rooms_left(user_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn once_joined( &self, user_id: &UserId, @@ -513,7 +519,7 @@ impl Service { self.db.once_joined(user_id, room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn is_joined( &self, user_id: &UserId, @@ -522,7 +528,7 @@ impl Service { self.db.is_joined(user_id, room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn is_invited( &self, user_id: &UserId, @@ -531,7 +537,7 @@ impl Service { self.db.is_invited(user_id, room_id) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn is_left( &self, user_id: &UserId, diff --git a/src/service/rooms/state_compressor.rs b/src/service/rooms/state_compressor.rs index 60fbb9c5..90ae4d80 100644 --- a/src/service/rooms/state_compressor.rs +++ b/src/service/rooms/state_compressor.rs @@ -10,7 +10,7 @@ use ruma::{EventId, RoomId}; use super::short::{ShortEventId, ShortStateHash, ShortStateKey}; use crate::{ - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, services, utils, Result, }; @@ -86,7 +86,7 @@ impl Service { /// Returns a stack with info on shortstatehash, full state, added diff and /// removed diff for the selected shortstatehash and each parent layer. #[allow(clippy::type_complexity)] - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn load_shortstatehash_info( &self, shortstatehash: ShortStateHash, @@ -191,7 +191,7 @@ impl Service { /// * `parent_states` - A stack with info on shortstatehash, full state, /// added diff and removed diff for each parent layer #[allow(clippy::type_complexity)] - #[tracing::instrument(skip( + #[t::instrument(skip( self, statediffnew, statediffremoved, @@ -314,7 +314,7 @@ impl Service { /// Returns the new shortstatehash, and the state diff from the previous /// room state #[allow(clippy::type_complexity)] - #[tracing::instrument(skip(self, new_state_ids_compressed))] + #[t::instrument(skip(self, new_state_ids_compressed))] pub(crate) fn save_state( &self, room_id: &RoomId, diff --git a/src/service/rooms/timeline.rs b/src/service/rooms/timeline.rs index d8cfa368..ada3fd3a 100644 --- a/src/service/rooms/timeline.rs +++ b/src/service/rooms/timeline.rs @@ -26,12 +26,11 @@ use ruma::{ use serde::Deserialize; use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use tokio::sync::RwLock; -use tracing::{error, info, warn}; use super::{short::ShortRoomId, state_compressor::CompressedStateEvent}; use crate::{ api::server_server, - observability::{FoundIn, Lookup, METRICS}, + observability::{prelude::*, FoundIn, Lookup, METRICS}, service::{ appservice::NamespaceRegex, globals::{marker, SigningKeys}, @@ -131,7 +130,7 @@ impl Service { } } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn first_pdu_in_room( &self, room_id: &RoomId, @@ -142,7 +141,7 @@ impl Service { .transpose() } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn last_timeline_count( &self, sender_user: &UserId, @@ -162,7 +161,7 @@ impl Service { .find_map(|x| match x { Ok(x) => Some(x), Err(error) => { - error!(%error, "Bad pdu in pdus_since"); + t::error!(%error, "Bad pdu in pdus_since"); None } }) @@ -259,7 +258,7 @@ impl Service { } /// Removes a pdu and creates a new one with the same id. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn replace_pdu( &self, pdu_id: &PduId, @@ -277,7 +276,7 @@ impl Service { /// happens in `append_pdu`. /// /// Returns pdu id - #[tracing::instrument(skip(self, pdu, pdu_json, leaves))] + #[t::instrument(skip(self, pdu, pdu_json, leaves))] pub(crate) async fn append_pdu( &self, pdu: &PduEvent, @@ -331,7 +330,7 @@ impl Service { } } } else { - error!("Invalid unsigned type in pdu"); + t::error!("Invalid unsigned type in pdu"); } } @@ -555,7 +554,7 @@ impl Service { if user.server_name() == services().globals.server_name() { - info!( + t::info!( %user, %room, reason, @@ -880,7 +879,7 @@ impl Service { |k, s| auth_events.get(&(k.clone(), s.to_owned())), ) .map_err(|error| { - error!(%error, "Auth check failed"); + t::error!(%error, "Auth check failed"); Error::BadDatabase("Auth check failed.") })?; @@ -948,7 +947,7 @@ impl Service { /// Creates a new persisted data unit and adds it to a room. This function /// takes a roomid_mutex_state, meaning that only this function is able /// to mutate the room state. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) async fn build_and_append_pdu( &self, pdu_builder: PduBuilder, @@ -962,7 +961,9 @@ impl Service { if admin_room == **room_id { match pdu.event_type() { TimelineEventType::RoomEncryption => { - warn!("Encryption is not allowed in the admins room"); + t::warn!( + "Encryption is not allowed in the admins room" + ); return Err(Error::BadRequest( ErrorKind::forbidden(), "Encryption is not allowed in the admins room.", @@ -997,7 +998,7 @@ impl Service { if content.membership == MembershipState::Leave { if target == server_user { - warn!( + t::warn!( "Grapevine user cannot leave from admins \ room" ); @@ -1017,7 +1018,7 @@ impl Service { .filter(|m| m != target) .count(); if count < 2 { - warn!( + t::warn!( "Last admin cannot leave from admins room" ); return Err(Error::BadRequest( @@ -1031,7 +1032,7 @@ impl Service { && pdu.state_key().is_some() { if target == server_user { - warn!( + t::warn!( "Grapevine user cannot be banned in \ admins room" ); @@ -1051,7 +1052,7 @@ impl Service { .filter(|m| m != target) .count(); if count < 2 { - warn!( + t::warn!( "Last admin cannot be banned in admins \ room" ); @@ -1164,7 +1165,7 @@ impl Service { /// Append the incoming event setting the state snapshot to the state from /// the server that sent the event. - #[tracing::instrument(skip_all)] + #[t::instrument(skip_all)] pub(crate) async fn append_incoming_pdu( &self, pdu: &PduEvent, @@ -1215,7 +1216,7 @@ impl Service { /// Returns an iterator over all events and their tokens in a room that /// happened before the event with id `until` in reverse-chronological /// order. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn pdus_until<'a>( &'a self, user_id: &UserId, @@ -1227,7 +1228,7 @@ impl Service { /// Returns an iterator over all events and their token in a room that /// happened after the event with id `from` in chronological order. - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn pdus_after<'a>( &'a self, user_id: &UserId, @@ -1238,7 +1239,7 @@ impl Service { } /// Replace a PDU with the redacted form. - #[tracing::instrument(skip(self, reason))] + #[t::instrument(skip(self, reason))] pub(crate) fn redact_pdu( &self, event_id: &EventId, @@ -1282,7 +1283,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, room_id))] + #[t::instrument(skip(self, room_id))] pub(crate) async fn backfill_if_required( &self, room_id: &RoomId, @@ -1319,7 +1320,7 @@ impl Service { // Request backfill for backfill_server in admin_servers { - info!(server = %backfill_server, "Asking server for backfill"); + t::info!(server = %backfill_server, "Asking server for backfill"); let response = services() .sending .send_federation_request( @@ -1339,13 +1340,13 @@ impl Service { .backfill_pdu(backfill_server, pdu, &pub_key_map) .await { - warn!(%error, "Failed to add backfilled pdu"); + t::warn!(%error, "Failed to add backfilled pdu"); } } return Ok(()); } Err(error) => { - warn!( + t::warn!( server = %backfill_server, %error, "Server could not provide backfill", @@ -1354,11 +1355,11 @@ impl Service { } } - info!("No servers could backfill"); + t::info!("No servers could backfill"); Ok(()) } - #[tracing::instrument(skip(self, pdu))] + #[t::instrument(skip(self, pdu))] pub(crate) async fn backfill_pdu( &self, origin: &ServerName, @@ -1377,7 +1378,7 @@ impl Service { // Skip the PDU if we already have it as a timeline event if let Some(pdu_id) = self.get_pdu_id(&event_id)? { - info!(%event_id, ?pdu_id, "We already know this event"); + t::info!(%event_id, ?pdu_id, "We already know this event"); return Ok(()); } @@ -1442,7 +1443,7 @@ impl Service { } drop(federation_token); - info!("Prepended backfill pdu"); + t::info!("Prepended backfill pdu"); Ok(()) } } diff --git a/src/service/sending.rs b/src/service/sending.rs index 1c3b6ecb..de4dadfe 100644 --- a/src/service/sending.rs +++ b/src/service/sending.rs @@ -34,7 +34,7 @@ use tokio::{ select, sync::{mpsc, Mutex, Semaphore}, }; -use tracing::{debug, error, warn, Span}; +use tracing::Span; use super::rooms::timeline::PduId; use crate::{ @@ -42,6 +42,7 @@ use crate::{ appservice_server, server_server::{self, AllowLoopbackRequests, LogRequestError}, }, + observability::prelude::*, services, utils::{calculate_hash, debug_slice_truncated}, Config, Error, PduEvent, Result, @@ -60,7 +61,7 @@ pub(crate) enum Destination { } impl Destination { - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn get_prefix(&self) -> Vec { let mut prefix = match self { Destination::Appservice(server) => { @@ -196,7 +197,7 @@ impl Service { initial_transactions.entry(destination.clone()).or_default(); if entry.len() > 30 { - warn!( + t::warn!( ?key, ?destination, ?event, @@ -240,7 +241,7 @@ impl Service { } } - #[tracing::instrument( + #[t::instrument( skip(self, result, handler_span, current_transaction_status), fields( current_status = ?current_transaction_status.get( @@ -266,7 +267,7 @@ impl Service { } if let Err(error) = result { - warn!(%error, "Marking transaction as failed"); + t::warn!(%error, "Marking transaction as failed"); current_transaction_status.entry(destination).and_modify(|e| { use TransactionStatus::{Failed, Retrying, Running}; @@ -274,7 +275,7 @@ impl Service { Running => Failed(1, Instant::now()), Retrying(n) => Failed(*n + 1, Instant::now()), Failed(..) => { - error!("Request that was not even running failed?!"); + t::error!("Request that was not even running failed?!"); return; } } @@ -308,7 +309,7 @@ impl Service { })) } - #[tracing::instrument( + #[t::instrument( skip(self, event_type, key, requester_span, current_transaction_status), fields( current_status = ?current_transaction_status.get(&destination), @@ -333,7 +334,7 @@ impl Service { current_transaction_status, ) { Ok(SelectedEvents::Retries(events)) => { - debug!("Retrying old events"); + t::debug!("Retrying old events"); Some(HandlerInputs { destination, events, @@ -341,7 +342,7 @@ impl Service { }) } Ok(SelectedEvents::New(events)) => { - debug!("Sending new event"); + t::debug!("Sending new event"); Some(HandlerInputs { destination, events, @@ -349,17 +350,17 @@ impl Service { }) } Ok(SelectedEvents::None) => { - debug!("Holding off from sending any events"); + t::debug!("Holding off from sending any events"); None } Err(error) => { - error!(%error, "Failed to select events to send"); + t::error!(%error, "Failed to select events to send"); None } } } - #[tracing::instrument( + #[t::instrument( skip(self, new_events, current_transaction_status), fields( new_events = debug_slice_truncated(&new_events, 3), @@ -446,7 +447,7 @@ impl Service { } } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn select_edus( &self, server_name: &ServerName, @@ -567,7 +568,7 @@ impl Service { Ok((events, max_edu_count)) } - #[tracing::instrument(skip(self, pdu_id, user, pushkey))] + #[t::instrument(skip(self, pdu_id, user, pushkey))] pub(crate) fn send_push_pdu( &self, pdu_id: &PduId, @@ -590,7 +591,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, servers, pdu_id))] + #[t::instrument(skip(self, servers, pdu_id))] pub(crate) fn send_pdu>( &self, servers: I, @@ -622,7 +623,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, server, serialized))] + #[t::instrument(skip(self, server, serialized))] pub(crate) fn send_reliable_edu( &self, server: &ServerName, @@ -645,7 +646,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self))] + #[t::instrument(skip(self))] pub(crate) fn send_pdu_appservice( &self, appservice_id: String, @@ -667,7 +668,7 @@ impl Service { Ok(()) } - #[tracing::instrument(skip(self, request))] + #[t::instrument(skip(self, request))] pub(crate) async fn send_federation_request( &self, destination: &ServerName, @@ -676,9 +677,9 @@ impl Service { where T: OutgoingRequest + Debug, { - debug!("Waiting for permit"); + t::debug!("Waiting for permit"); let permit = self.maximum_requests.acquire().await; - debug!("Got permit"); + t::debug!("Got permit"); let response = tokio::time::timeout( Duration::from_secs(2 * 60), server_server::send_request( @@ -690,7 +691,7 @@ impl Service { ) .await .map_err(|_| { - warn!("Timeout waiting for server response"); + t::warn!("Timeout waiting for server response"); Error::BadServerResponse("Timeout waiting for server response") })?; drop(permit); @@ -702,7 +703,7 @@ impl Service { /// /// Only returns None if there is no url specified in the appservice /// registration file - #[tracing::instrument( + #[t::instrument( skip(self, registration, request), fields(appservice_id = registration.id), )] @@ -723,7 +724,7 @@ impl Service { } } -#[tracing::instrument(skip(events))] +#[t::instrument(skip(events))] async fn handle_appservice_event( id: &str, events: Vec, @@ -778,7 +779,7 @@ async fn handle_appservice_event( Ok(()) } -#[tracing::instrument(skip(events))] +#[t::instrument(skip(events))] async fn handle_push_event( userid: &UserId, pushkey: &str, @@ -861,7 +862,7 @@ async fn handle_push_event( Ok(()) } -#[tracing::instrument(skip(events))] +#[t::instrument(skip(events))] async fn handle_federation_event( server: &ServerName, events: Vec, @@ -880,7 +881,7 @@ async fn handle_federation_event( .timeline .get_pdu_json_from_id(pdu_id)? .ok_or_else(|| { - error!(pdu_id = ?pdu_id, "PDU not found"); + t::error!(pdu_id = ?pdu_id, "PDU not found"); Error::bad_database( "[Normal] Event in servernamevent_datas not \ found in db.", @@ -917,7 +918,12 @@ async fn handle_federation_event( for pdu in response.pdus { if let (event_id, Err(error)) = pdu { - warn!(%server, %event_id, %error, "Failed to send event to server"); + t::warn!( + %server, + %event_id, + %error, + "Failed to send event to server" + ); } } @@ -926,7 +932,7 @@ async fn handle_federation_event( Ok(()) } -#[tracing::instrument(skip_all)] +#[t::instrument(skip_all)] async fn handle_events( HandlerInputs { destination, diff --git a/src/service/uiaa.rs b/src/service/uiaa.rs index 566db934..499878e4 100644 --- a/src/service/uiaa.rs +++ b/src/service/uiaa.rs @@ -7,10 +7,10 @@ use ruma::{ }, CanonicalJsonValue, DeviceId, OwnedDeviceId, OwnedUserId, UserId, }; -use tracing::error; use crate::{ - api::client_server::SESSION_ID_LENGTH, services, utils, Error, Result, + api::client_server::SESSION_ID_LENGTH, observability::prelude::*, services, + utils, Error, Result, }; mod data; @@ -137,7 +137,7 @@ impl Service { AuthData::Dummy(_) => { uiaainfo.completed.push(AuthType::Dummy); } - kind => error!(?kind, "Auth kind not supported"), + kind => t::error!(?kind, "Auth kind not supported"), } // Check if a flow now succeeds diff --git a/src/utils.rs b/src/utils.rs index 45211399..71229ffc 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -15,7 +15,7 @@ use ruma::{ CanonicalJsonError, CanonicalJsonObject, MxcUri, MxcUriError, OwnedMxcUri, }; -use crate::{Error, Result}; +use crate::{observability::prelude::*, Error, Result}; pub(crate) mod error; pub(crate) mod on_demand_hashmap; @@ -108,7 +108,7 @@ where Argon2::default().verify_password(password.as_ref(), &hash).is_ok() } -#[tracing::instrument(skip(keys))] +#[t::instrument(skip(keys))] pub(crate) fn calculate_hash<'a, I, T>(keys: I) -> Vec where I: IntoIterator, @@ -234,8 +234,8 @@ impl fmt::Debug for TruncatedDebugSlice<'_, T> { pub(crate) fn debug_slice_truncated( slice: &[T], max_len: usize, -) -> tracing::field::DebugValue> { - tracing::field::debug(TruncatedDebugSlice { +) -> t::field::DebugValue> { + t::field::debug(TruncatedDebugSlice { inner: slice, max_len, }) diff --git a/src/utils/error.rs b/src/utils/error.rs index 49b5ab15..d855d737 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -9,9 +9,8 @@ use ruma::{ OwnedServerName, }; use thiserror::Error; -use tracing::{error, warn}; -use crate::Ra; +use crate::{observability::prelude::*, Ra}; pub(crate) type Result = std::result::Result; @@ -88,12 +87,12 @@ pub(crate) enum Error { impl Error { pub(crate) fn bad_database(message: &'static str) -> Self { - error!(message, "Bad database"); + t::error!(message, "Bad database"); Self::BadDatabase(message) } pub(crate) fn bad_config(message: &'static str) -> Self { - error!(message, "Bad config"); + t::error!(message, "Bad config"); Self::BadConfig(message) } @@ -156,7 +155,7 @@ impl Error { _ => (Unknown, StatusCode::INTERNAL_SERVER_ERROR), }; - warn!(%status_code, error = %message, "Responding with an error"); + t::warn!(%status_code, error = %message, "Responding with an error"); Ra(UiaaResponse::MatrixError(RumaError { body: ErrorBody::Standard { diff --git a/src/utils/on_demand_hashmap.rs b/src/utils/on_demand_hashmap.rs index 69e8bac9..8275e8db 100644 --- a/src/utils/on_demand_hashmap.rs +++ b/src/utils/on_demand_hashmap.rs @@ -8,9 +8,8 @@ use std::{ }; use tokio::sync::{mpsc, Mutex, OwnedMutexGuard, RwLock}; -use tracing::{trace, warn, Level}; -use crate::observability::METRICS; +use crate::observability::{prelude::*, METRICS}; /// Data shared between [`OnDemandHashMap`] and the cleanup task /// @@ -28,8 +27,8 @@ impl SharedData where K: Hash + Eq + Clone + fmt::Debug, { - #[tracing::instrument( - level = Level::TRACE, + #[t::instrument( + level = t::Level::TRACE, skip(self), fields(name = self.name.as_ref()), )] @@ -37,21 +36,21 @@ where let mut map = self.entries.write().await; let Some(weak) = map.get(&key) else { - trace!("Entry has already been cleaned up"); + t::trace!("Entry has already been cleaned up"); return; }; if weak.strong_count() != 0 { - trace!("Entry is in use"); + t::trace!("Entry is in use"); return; } - trace!("Cleaning up unused entry"); + t::trace!("Cleaning up unused entry"); map.remove(&key); METRICS.record_on_demand_hashmap_size(self.name.clone(), map.len()); } - #[tracing::instrument(level = Level::TRACE, skip(map))] + #[t::instrument(level = t::Level::TRACE, skip(map))] fn try_get_live_value( pass: usize, map: &HashMap>, @@ -59,16 +58,16 @@ where ) -> Option> { if let Some(value) = map.get(key) { if let Some(value) = value.upgrade() { - trace!(pass, "Using existing value"); + t::trace!(pass, "Using existing value"); return Some(value); } - trace!( + t::trace!( pass, "Existing value is stale and needs cleanup, creating new" ); } else { - trace!(pass, "No existing value, creating new"); + t::trace!(pass, "No existing value, creating new"); } None @@ -76,7 +75,7 @@ where /// Either returns an existing live value, or creates a new one and inserts /// it into the map. - #[tracing::instrument(level = Level::TRACE, skip(self, create))] + #[t::instrument(level = t::Level::TRACE, skip(self, create))] async fn get_or_insert_with(&self, key: &K, create: F) -> Arc where F: FnOnce() -> V, @@ -145,7 +144,7 @@ where tokio::task::spawn(async move { loop { let Some(key) = receiver.recv().await else { - trace!( + t::trace!( name = shared.name.as_ref(), "Channel has died, exiting cleanup task" ); @@ -163,7 +162,7 @@ where } } - #[tracing::instrument(level = Level::TRACE, skip(self, create))] + #[t::instrument(level = t::Level::TRACE, skip(self, create))] pub(crate) async fn get_or_insert_with( &self, key: K, @@ -193,14 +192,14 @@ struct EntryDropGuard { impl Drop for EntryDropGuard { fn drop(&mut self) { let Some(cleanup_sender) = self.cleanup_sender.upgrade() else { - trace!("Backing map has already been dropped"); + t::trace!("Backing map has already been dropped"); return; }; if let Err(error) = cleanup_sender .send(self.key.take().expect("drop should only be called once")) { - warn!(%error, "Failed to send cleanup message"); + t::warn!(%error, "Failed to send cleanup message"); }; } } @@ -252,7 +251,7 @@ where /// Locks this key in the `TokenSet`, returning a token proving /// unique access. - #[tracing::instrument(level = Level::TRACE, skip(self))] + #[t::instrument(level = t::Level::TRACE, skip(self))] pub(crate) async fn lock_key(&self, key: K) -> KeyToken { let Entry { drop_guard, diff --git a/src/utils/proxy_protocol.rs b/src/utils/proxy_protocol.rs index 53021755..5e260f6c 100644 --- a/src/utils/proxy_protocol.rs +++ b/src/utils/proxy_protocol.rs @@ -11,7 +11,8 @@ use tokio::{ time::{timeout, Timeout}, }; use tower::Layer; -use tracing::warn; + +use crate::observability::prelude::*; #[derive(Debug, Clone)] pub(crate) struct ProxyAcceptorConfig { @@ -138,13 +139,16 @@ where let stream = ret .map_err(|e| { - warn!( + t::warn!( "Timed out waiting for HAProxy protocol header" ); std::io::Error::new(ErrorKind::TimedOut, e) })? .inspect_err(|error| { - warn!(%error, "Failed to parse HAProxy protocol header"); + t::warn!( + %error, + "Failed to parse HAProxy protocol header" + ); })?; let service = From d28135f7ca88d706ef424674ee0cf0145b3dcc9a Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Fri, 13 Dec 2024 22:30:48 -0800 Subject: [PATCH 04/12] add helper macros to log error source chains The specific thing that prompted this is that Error::Reqwest only logs the Display impl of reqwest::Error, while the actual information you need to determine what went wrong is usually buried deeper in the source chain. This makes debugging federation networking issues super frustrating. Instead of just fixing this one case, let's just log the source chains everywhere. What could go wrong? --- src/observability/prelude.rs | 113 +++++++++++++++++++++++++++++++++++ 1 file changed, 113 insertions(+) diff --git a/src/observability/prelude.rs b/src/observability/prelude.rs index a991e8f7..80e328f6 100644 --- a/src/observability/prelude.rs +++ b/src/observability/prelude.rs @@ -11,3 +11,116 @@ pub(crate) use tracing as t; pub(crate) use tracing::Instrument; + +/// [`tracing::event!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +#[allow(unused)] +macro_rules! event_err { + ($level:expr, $error:expr, $($rest:tt)+) => { + ::tracing::event!( + $level, + error=%::wee_woo::ErrorExt::display_with_sources(&$error, " -> "), + $($rest)+ + ) + } +} + +/// [`tracing::trace!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +macro_rules! trace_err { + ($error:expr, $($rest:tt)+) => { + $crate::observability::prelude::event_err!( + ::tracing::Level::TRACE, + $error, + $($rest)+ + ) + } +} + +/// [`tracing::debug!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +macro_rules! debug_err { + ($error:expr, $($rest:tt)+) => { + $crate::observability::prelude::event_err!( + ::tracing::Level::DEBUG, + $error, + $($rest)+ + ) + } +} + +/// [`tracing::info!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +macro_rules! info_err { + ($error:expr, $($rest:tt)+) => { + $crate::observability::prelude::event_err!( + ::tracing::Level::INFO, + $error, + $($rest)+ + ) + } +} + +/// [`tracing::warn!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +macro_rules! warn_err { + ($error:expr, $($rest:tt)+) => { + $crate::observability::prelude::event_err!( + ::tracing::Level::WARN, + $error, + $($rest)+ + ) + } +} + +/// [`tracing::error!`] but takes an error and formats its source chain as an +/// `error` field. +/// +/// The `parent:` and `target:` arguments from the original macro are not +/// supported. +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +macro_rules! error_err { + ($error:expr, $($rest:tt)+) => { + $crate::observability::prelude::event_err!( + ::tracing::Level::ERROR, + $error, + $($rest)+ + ) + } +} + +// Allowed because all of these variants exist for completeness, even if they +// aren't currently used. +#[allow(unused)] +pub(crate) use { + debug_err, error_err, event_err, info_err, trace_err, warn_err, +}; From a3448b5c845c44ed28d28fce8746b1250fafa1d4 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 01:42:59 -0800 Subject: [PATCH 05/12] switch all error logs to using *_err macros --- src/api/appservice_server.rs | 10 +++---- src/api/client_server/directory.rs | 4 +-- src/api/client_server/keys.rs | 2 +- src/api/client_server/media.rs | 18 ++++--------- src/api/client_server/membership.rs | 26 +++++++++--------- src/api/client_server/profile.rs | 4 +-- src/api/client_server/room.rs | 4 +-- src/api/client_server/sync.rs | 2 +- src/api/client_server/sync/msc3575.rs | 2 +- src/api/client_server/sync/v3.rs | 6 ++--- src/api/ruma_wrapper/axum.rs | 16 +++++------ src/api/server_server.rs | 39 ++++++++++++++------------- src/database.rs | 10 +++---- src/observability/prelude.rs | 1 - src/service/admin.rs | 4 +-- src/service/globals.rs | 4 +-- src/service/media.rs | 25 +++++++++-------- src/service/pdu.rs | 2 +- src/service/pusher.rs | 12 ++++----- src/service/rooms/auth_chain.rs | 4 +-- src/service/rooms/event_handler.rs | 35 ++++++++++++------------ src/service/rooms/spaces.rs | 28 +++++++++---------- src/service/rooms/state.rs | 2 +- src/service/rooms/state_accessor.rs | 4 +-- src/service/rooms/state_cache.rs | 14 +++++----- src/service/rooms/timeline.rs | 10 +++---- src/service/sending.rs | 4 +-- src/utils/on_demand_hashmap.rs | 2 +- src/utils/proxy_protocol.rs | 4 +-- 29 files changed, 145 insertions(+), 153 deletions(-) diff --git a/src/api/appservice_server.rs b/src/api/appservice_server.rs index 49383f22..aa2683ad 100644 --- a/src/api/appservice_server.rs +++ b/src/api/appservice_server.rs @@ -62,8 +62,8 @@ where .execute(reqwest_request) .await .inspect_err(|error| { - t::warn!( - %error, + warn_err!( + error, appservice = registration.id, %destination, "Could not send request to appservice", @@ -83,7 +83,7 @@ where // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - t::warn!(%error, "Server error"); + warn_err!(error, "Server error"); Vec::new().into() }); @@ -107,8 +107,8 @@ where ); response.map(Some).map_err(|error| { - t::warn!( - %error, + warn_err!( + error, appservice = %destination, %url, "Appservice returned invalid response bytes", diff --git a/src/api/client_server/directory.rs b/src/api/client_server/directory.rs index 86731348..84873b90 100644 --- a/src/api/client_server/directory.rs +++ b/src/api/client_server/directory.rs @@ -371,8 +371,8 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result { _ => None, }) .map_err(|error| { - t::error!( - %error, + error_err!( + error, "Invalid room join rule event in database" ); Error::BadDatabase( diff --git a/src/api/client_server/keys.rs b/src/api/client_server/keys.rs index cee61d50..f697c6c9 100644 --- a/src/api/client_server/keys.rs +++ b/src/api/client_server/keys.rs @@ -505,7 +505,7 @@ async fn request_keys_from( match &result { Ok(_) => reset_key_request_back_off(server).await, Err(error) => { - t::debug!(%server, %error, "remote device key query failed"); + debug_err!(error, %server, "remote device key query failed"); back_off_key_requests(server.to_owned()).await; } } diff --git a/src/api/client_server/media.rs b/src/api/client_server/media.rs index 3b8a04d6..39e202af 100644 --- a/src/api/client_server/media.rs +++ b/src/api/client_server/media.rs @@ -212,7 +212,7 @@ async fn get_redirected_content( location: String, ) -> Result { let location = location.parse().map_err(|error| { - t::warn!(location, %error, "Invalid redirect location"); + warn_err!(error, location, "Invalid redirect location"); Error::BadServerResponse("Invalid redirect location") })?; let response = services() @@ -226,11 +226,7 @@ async fn get_redirected_content( .get(CONTENT_TYPE) .map(|value| { value.to_str().map_err(|error| { - t::error!( - ?value, - %error, - "Invalid Content-Type header" - ); + error_err!(error, ?value, "Invalid Content-Type header"); Error::BadServerResponse("Invalid Content-Type header") }) }) @@ -242,11 +238,7 @@ async fn get_redirected_content( .get(CONTENT_DISPOSITION) .map(|value| { ContentDisposition::try_from(value.as_bytes()).map_err(|error| { - t::error!( - ?value, - %error, - "Invalid Content-Disposition header" - ); + error_err!(error, ?value, "Invalid Content-Disposition header"); Error::BadServerResponse("Invalid Content-Disposition header") }) }) @@ -895,8 +887,8 @@ async fn get_content_thumbnail_route_ruma( resp.content.content_type, )); } - Err(error) => t::warn!( - %error, + Err(error) => warn_err!( + error, "Failed to fetch thumbnail via federation, trying to fetch \ original media and create thumbnail ourselves" ), diff --git a/src/api/client_server/membership.rs b/src/api/client_server/membership.rs index 4d7c5cb6..cef9b792 100644 --- a/src/api/client_server/membership.rs +++ b/src/api/client_server/membership.rs @@ -537,7 +537,7 @@ async fn join_room_by_id_helper( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()) .map_err(|error| { - t::warn!(%error, "Invalid join rules event"); + warn_err!(error, "Invalid join rules event"); Error::bad_database( "Invalid join rules event in db.", ) @@ -956,8 +956,8 @@ async fn join_room_by_id_helper( .insert(remote_server.to_string(), signature.clone()); } Err(error) => { - t::warn!( - %error, + warn_err!( + error, server = %remote_server, event = ?signed_value, "Other server sent invalid signature in sendjoin \ @@ -999,8 +999,8 @@ async fn join_room_by_id_helper( let pdu = PduEvent::from_id_val(&event_id, value.clone()).map_err( |error| { - t::warn!( - %error, + warn_err!( + error, object = ?value, "Invalid PDU in send_join response", ); @@ -1062,7 +1062,7 @@ async fn join_room_by_id_helper( }, ) .map_err(|error| { - t::warn!(%error, "Auth check failed"); + warn_err!(error, "Auth check failed"); Error::BadRequest(ErrorKind::InvalidParam, "Auth check failed") })?; @@ -1164,8 +1164,8 @@ async fn make_join_request( return Ok((r, remote_server.clone())); } Err(error) => { - t::warn!( - %error, + warn_err!( + error, server = %remote_server, "Remote join request failed", ); @@ -1184,7 +1184,7 @@ async fn validate_and_add_event_id( ) -> Result<(OwnedEventId, CanonicalJsonObject)> { let mut value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - t::error!(%error, object = ?pdu, "Invalid PDU in server response"); + error_err!(error, object = ?pdu, "Invalid PDU in server response"); Error::BadServerResponse("Invalid PDU in server response") })?; let event_id = EventId::parse(format!( @@ -1258,9 +1258,9 @@ async fn validate_and_add_event_id( if let Err(error) = ruma::signatures::verify_event(&keys, &value, room_version) { - t::warn!( + warn_err!( + error, %event_id, - %error, ?pdu, "Event failed verification", ); @@ -1481,7 +1481,7 @@ pub(crate) async fn leave_all_rooms(user_id: &UserId) -> Result<()> { }; if let Err(error) = leave_room(user_id, &room_id, None).await { - t::warn!(%user_id, %room_id, %error, "Failed to leave room"); + warn_err!(error, %user_id, %room_id, "Failed to leave room"); } } @@ -1557,7 +1557,7 @@ pub(crate) async fn leave_room( .await?; } else { if let Err(error) = remote_leave_room(user_id, room_id).await { - t::warn!(%error, "Failed to leave room remotely"); + warn_err!(error, "Failed to leave room remotely"); // Don't tell the client about this error } diff --git a/src/api/client_server/profile.rs b/src/api/client_server/profile.rs index 3be9ab78..255c42e3 100644 --- a/src/api/client_server/profile.rs +++ b/src/api/client_server/profile.rs @@ -93,7 +93,7 @@ pub(crate) async fn set_displayname_route( .build_and_append_pdu(pdu_builder, sender_user, &room_token) .await { - t::warn!(%error, "failed to add PDU"); + warn_err!(error, "failed to add PDU"); } } @@ -205,7 +205,7 @@ pub(crate) async fn set_avatar_url_route( .build_and_append_pdu(pdu_builder, sender_user, &room_token) .await { - t::warn!(%error, "failed to add PDU"); + warn_err!(error, "failed to add PDU"); }; } diff --git a/src/api/client_server/room.rs b/src/api/client_server/room.rs index 93066238..781f5be9 100644 --- a/src/api/client_server/room.rs +++ b/src/api/client_server/room.rs @@ -400,7 +400,7 @@ pub(crate) async fn create_room_route( for event in &body.initial_state { let mut pdu_builder = event.deserialize_as::().map_err(|error| { - t::warn!(%error, "Invalid initial state event"); + warn_err!(error, "Invalid initial state event"); Error::BadRequest( ErrorKind::InvalidParam, "Invalid initial state event.", @@ -474,7 +474,7 @@ pub(crate) async fn create_room_route( invite_helper(sender_user, user_id, &room_id, None, body.is_direct) .await { - t::warn!(%error, "Invite helper failed"); + warn_err!(error, "Invite helper failed"); }; } diff --git a/src/api/client_server/sync.rs b/src/api/client_server/sync.rs index 200bcf15..0195c5ba 100644 --- a/src/api/client_server/sync.rs +++ b/src/api/client_server/sync.rs @@ -26,7 +26,7 @@ fn load_timeline( .filter_map(|x| match x { Ok(x) => Some(x), Err(error) => { - t::error!(%error, "Bad PDU in pdus_since"); + error_err!(error, "Bad PDU in pdus_since"); None } }) diff --git a/src/api/client_server/sync/msc3575.rs b/src/api/client_server/sync/msc3575.rs index 5a0b6765..d5424c61 100644 --- a/src/api/client_server/sync/msc3575.rs +++ b/src/api/client_server/sync/msc3575.rs @@ -605,7 +605,7 @@ pub(crate) async fn sync_events_v4_route( } match tokio::time::timeout(duration, watcher).await { Ok(x) => x.expect("watcher should succeed"), - Err(error) => t::debug!(%error, "Timed out"), + Err(error) => debug_err!(error, "Timed out"), }; } diff --git a/src/api/client_server/sync/v3.rs b/src/api/client_server/sync/v3.rs index aa111608..ebcc3691 100644 --- a/src/api/client_server/sync/v3.rs +++ b/src/api/client_server/sync/v3.rs @@ -279,7 +279,7 @@ pub(crate) async fn sync_events_route( } match tokio::time::timeout(duration, watcher).await { Ok(x) => x.expect("watcher should succeed"), - Err(error) => t::debug!(%error, "Timed out"), + Err(error) => debug_err!(error, "Timed out"), }; } Ok(Ra(response)) @@ -748,9 +748,9 @@ async fn load_joined_room( lazy_loaded.insert(state_key_userid); } Err(error) => { - t::error!( + error_err!( + error, event_id = %pdu.event_id, - %error, "Invalid state key for member event", ); } diff --git a/src/api/ruma_wrapper/axum.rs b/src/api/ruma_wrapper/axum.rs index 2084567b..4fc92cbe 100644 --- a/src/api/ruma_wrapper/axum.rs +++ b/src/api/ruma_wrapper/axum.rs @@ -84,7 +84,7 @@ async fn ar_from_request_inner( let query_params: QueryParams = match serde_html_form::from_str(query) { Ok(params) => params, Err(error) => { - t::error!(%error, %query, "Failed to deserialize query parameters"); + error_err!(error, %query, "Failed to deserialize query parameters"); return Err(Error::BadRequest( ErrorKind::Unknown, "Failed to read query parameters", @@ -184,8 +184,8 @@ async fn ar_from_request_inner( .extract::>>() .await .map_err(|error| { - t::warn!( - %error, + warn_err!( + error, "Missing or invalid Authorization header" ); @@ -283,7 +283,7 @@ async fn ar_from_request_inner( let keys = match keys_result { Ok(b) => b, Err(error) => { - t::warn!(%error, "Failed to fetch signing keys"); + warn_err!(error, "Failed to fetch signing keys"); return Err(Error::BadRequest( ErrorKind::forbidden(), "Failed to fetch signing keys.", @@ -309,8 +309,8 @@ async fn ar_from_request_inner( { Ok(()) => (None, None, Some(x_matrix.origin), None), Err(error) => { - t::warn!( - %error, + warn_err!( + error, origin = %x_matrix.origin, object = ?request_map, "Failed to verify JSON request" @@ -420,8 +420,8 @@ where let body = T::try_from_http_request(pieces.http_request, &pieces.path_params) .map_err(|error| { - t::warn!( - %error, + warn_err!( + error, body = ?pieces.json_body, "Request body JSON structure is incorrect" ); diff --git a/src/api/server_server.rs b/src/api/server_server.rs index 6d718c90..a2f41366 100644 --- a/src/api/server_server.rs +++ b/src/api/server_server.rs @@ -200,8 +200,8 @@ where &[MatrixVersion::V1_11], ) .map_err(|error| { - t::warn!( - %error, + warn_err!( + error, actual_destination = actual_destination_str, "Failed to find destination", ); @@ -289,7 +289,7 @@ where let mut response = response.inspect_err(|error| { if log_error == LogRequestError::Yes { - t::warn!(%error, "Could not send request"); + warn_err!(error, "Could not send request"); } })?; @@ -308,7 +308,7 @@ where t::debug!("Getting response bytes"); // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - t::warn!(%error, "Server error"); + warn_err!(error, "Server error"); Vec::new().into() }); t::debug!("Got response bytes"); @@ -345,7 +345,7 @@ where } response.map_err(|e| { - t::warn!(error = %e, "Invalid 200 response"); + warn_err!(e, "Invalid 200 response"); Error::BadServerResponse("Server returned bad 200 response.") }) } @@ -566,7 +566,7 @@ async fn request_well_known(destination: &str) -> Option { .await; t::debug!("Got well known response"); if let Err(error) = &response { - t::debug!(%error, "Failed to request .well-known"); + debug_err!(error, "Failed to request .well-known"); return None; } let text = response.ok()?.text().await; @@ -704,7 +704,7 @@ pub(crate) fn parse_incoming_pdu( ) -> Result<(OwnedEventId, CanonicalJsonObject, OwnedRoomId)> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()).map_err(|error| { - t::warn!(%error, object = ?pdu, "Error parsing incoming event"); + warn_err!(error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; @@ -750,7 +750,7 @@ pub(crate) async fn send_transaction_message_route( for pdu in &body.pdus { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - t::warn!(%error, object = ?pdu, "Error parsing incoming event"); + warn_err!(error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; let room_id: OwnedRoomId = value @@ -775,7 +775,7 @@ pub(crate) async fn send_transaction_message_route( let (event_id, value, room_id) = match r { Ok(t) => t, Err(error) => { - t::warn!(%error, object = ?pdu, "Error parsing incoming event"); + warn_err!(error, object = ?pdu, "Error parsing incoming event"); continue; } }; @@ -816,7 +816,7 @@ pub(crate) async fn send_transaction_message_route( for pdu in &resolved_map { if let (event_id, Err(error)) = pdu { if matches!(error, Error::BadRequest(ErrorKind::NotFound, _)) { - t::warn!(%error, %event_id, "Incoming PDU failed"); + warn_err!(error, %event_id, "Incoming PDU failed"); } } } @@ -968,8 +968,8 @@ pub(crate) async fn send_transaction_message_route( &ev_type.to_string(), event.deserialize_as().map_err( |error| { - t::warn!( - %error, + warn_err!( + error, object = ?event.json(), "To-Device event is invalid", ); @@ -1507,7 +1507,7 @@ pub(crate) async fn create_join_event_template_route( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()).map_err( |error| { - t::warn!(%error, "Invalid join rules event"); + warn_err!(error, "Invalid join rules event"); Error::bad_database("Invalid join rules event in db.") }, ) @@ -1604,7 +1604,7 @@ async fn create_join_event( .map(|join_rules_event| { serde_json::from_str(join_rules_event.content.get()).map_err( |error| { - t::warn!(%error, "Invalid join rules event"); + warn_err!(error, "Invalid join rules event"); Error::bad_database("Invalid join rules event in db.") }, ) @@ -1867,7 +1867,7 @@ pub(crate) async fn create_invite_route( let pdu: PduEvent = serde_json::from_value(event.into()).map_err(|error| { - t::warn!(%error, "Invalid invite event"); + warn_err!(error, "Invalid invite event"); Error::BadRequest(ErrorKind::InvalidParam, "Invalid invite event.") })?; @@ -2101,10 +2101,11 @@ pub(crate) async fn media_download_route( }; let content_disposition = content_disposition.and_then(|s| { - s.parse().inspect_err( - |error| t::warn!(%error, "Invalid Content-Disposition in database"), - ) - .ok() + s.parse() + .inspect_err(|error| { + warn_err!(error, "Invalid Content-Disposition in database"); + }) + .ok() }); Ok(Ra(authenticated_media::get_content::v1::Response { diff --git a/src/database.rs b/src/database.rs index caa56022..5ce48dfe 100644 --- a/src/database.rs +++ b/src/database.rs @@ -848,8 +848,8 @@ impl KeyValueDatabase { ) { Ok(u) => u, Err(error) => { - t::warn!( - %error, + warn_err!( + error, user_localpart = %username, "Invalid username", ); @@ -950,8 +950,8 @@ impl KeyValueDatabase { ) { Ok(u) => u, Err(error) => { - t::warn!( - %error, + warn_err!( + error, user_localpart = %username, "Invalid username", ); @@ -1062,7 +1062,7 @@ impl KeyValueDatabase { msg(); let start = Instant::now(); if let Err(error) = services().globals.cleanup() { - t::error!(%error, "cleanup: Error"); + error_err!(error, "cleanup: Error"); } else { t::debug!( elapsed = ?start.elapsed(), diff --git a/src/observability/prelude.rs b/src/observability/prelude.rs index 80e328f6..165d9913 100644 --- a/src/observability/prelude.rs +++ b/src/observability/prelude.rs @@ -17,7 +17,6 @@ pub(crate) use tracing::Instrument; /// /// The `parent:` and `target:` arguments from the original macro are not /// supported. -#[allow(unused)] macro_rules! event_err { ($level:expr, $error:expr, $($rest:tt)+) => { ::tracing::event!( diff --git a/src/service/admin.rs b/src/service/admin.rs index 2567c9d7..07c19605 100644 --- a/src/service/admin.rs +++ b/src/service/admin.rs @@ -1068,9 +1068,9 @@ impl Service { if leave_rooms { for &user_id in &user_ids { if let Err(error) = leave_all_rooms(user_id).await { - t::warn!( + warn_err!( + error, %user_id, - %error, "failed to leave one or more rooms" ); } diff --git a/src/service/globals.rs b/src/service/globals.rs index 7b5f6ff4..83d32b74 100644 --- a/src/service/globals.rs +++ b/src/service/globals.rs @@ -502,8 +502,8 @@ impl Service { } } Err(error) => { - t::error!( - %error, + error_err!( + error, "Could not set the configured emergency password for the \ Grapevine user", ); diff --git a/src/service/media.rs b/src/service/media.rs index 2ea69782..84e5664c 100644 --- a/src/service/media.rs +++ b/src/service/media.rs @@ -110,11 +110,10 @@ impl Service { any_files = true; self.delete_by_key(thumbnail_key.clone()).await.inspect_err( |error| { - t::warn!( - thumbnail_key = utils::u8_slice_to_hex( - thumbnail_key.as_bytes() - ), - %error, + warn_err!( + error, + thumbnail_key = + utils::u8_slice_to_hex(thumbnail_key.as_bytes()), "Failed to delete thumbnail media" ); }, @@ -122,14 +121,14 @@ impl Service { } if let Some((_, key)) = - self.db.search_file_metadata(mxc, 0, 0).inspect_err( - |error| t::warn!(%error, "Failed to find original media key"), - )? + self.db.search_file_metadata(mxc, 0, 0).inspect_err(|error| { + warn_err!(error, "Failed to find original media key"); + })? { any_files = true; - self.delete_by_key(key).await.inspect_err( - |error| t::warn!(%error, "Failed to delete original media"), - )?; + self.delete_by_key(key).await.inspect_err(|error| { + warn_err!(error, "Failed to delete original media"); + })?; } if any_files { @@ -137,7 +136,7 @@ impl Service { } else { let error = Error::BadRequest(ErrorKind::NotFound, "Media not found"); - t::warn!(%error, "Failed to delete media"); + warn_err!(error, "Failed to delete media"); Err(error) } } @@ -218,7 +217,7 @@ impl Service { let image = match image::load_from_memory(file) { Ok(image) => image, Err(error) => { - t::warn!(%error, "Failed to parse source image"); + warn_err!(error, "Failed to parse source image"); return Ok(None); } }; diff --git a/src/service/pdu.rs b/src/service/pdu.rs index 2eb4a048..46593c79 100644 --- a/src/service/pdu.rs +++ b/src/service/pdu.rs @@ -474,7 +474,7 @@ pub(crate) fn gen_event_id_canonical_json( ) -> crate::Result<(OwnedEventId, CanonicalJsonObject)> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()).map_err(|error| { - t::warn!(%error, object = ?pdu, "Error parsing incoming event"); + warn_err!(error, object = ?pdu, "Error parsing incoming event"); Error::BadServerResponse("Invalid PDU in server response") })?; diff --git a/src/service/pusher.rs b/src/service/pusher.rs index d132ea14..26d43ed9 100644 --- a/src/service/pusher.rs +++ b/src/service/pusher.rs @@ -82,7 +82,7 @@ impl Service { &[MatrixVersion::V1_0], ) .map_err(|error| { - t::warn!(%error, %destination, "Failed to find destination"); + warn_err!(error, %destination, "Failed to find destination"); Error::BadServerResponse("Invalid destination") })? .map(BytesMut::freeze); @@ -109,7 +109,7 @@ impl Service { // TODO: handle timeout let body = response.bytes().await.unwrap_or_else(|error| { - t::warn!(%error, "Server error"); + warn_err!(error, "Server error"); Vec::new().into() }); @@ -132,8 +132,8 @@ impl Service { .expect("reqwest body is valid http body"), ); response.map_err(|error| { - t::warn!( - %error, + warn_err!( + error, appservice = %destination, %url, "Push gateway returned invalid response bytes", @@ -144,8 +144,8 @@ impl Service { }) } Err(error) => { - t::warn!( - %error, + warn_err!( + error, %destination, "Could not send request to push gateway", ); diff --git a/src/service/rooms/auth_chain.rs b/src/service/rooms/auth_chain.rs index 0f54b312..ff9d8ff1 100644 --- a/src/service/rooms/auth_chain.rs +++ b/src/service/rooms/auth_chain.rs @@ -223,9 +223,9 @@ impl Service { ); } Err(error) => { - t::error!( + error_err!( + error, ?event_id, - ?error, "Could not load event in auth chain" ); } diff --git a/src/service/rooms/event_handler.rs b/src/service/rooms/event_handler.rs index 12e0fcea..f867505b 100644 --- a/src/service/rooms/event_handler.rs +++ b/src/service/rooms/event_handler.rs @@ -242,7 +242,7 @@ impl Service { .await { errors += 1; - t::warn!(%error, event_id = %prev_id, "Prev event failed"); + warn_err!(error, event_id = %prev_id, "Prev event failed"); match services() .globals .bad_event_ratelimiter @@ -380,7 +380,7 @@ impl Service { ) { Err(error) => { // Drop - t::warn!(%event_id, %error, "Dropping bad event"); + warn_err!(error, %event_id, "Dropping bad event"); return Err(Error::BadRequest( ErrorKind::InvalidParam, "Signature verification failed", @@ -733,9 +733,10 @@ impl Service { |event_id| { let res = services().rooms.timeline.get_pdu(event_id); if let Err(error) = &res { - t::error!( - %error, - %event_id, "Failed to fetch event" + error_err!( + error, + %event_id, + "Failed to fetch event" ); } res.ok().flatten() @@ -760,10 +761,10 @@ impl Service { .collect::>()?, ), Err(error) => { - t::warn!( - %error, + warn_err!( + error, "State resolution on prev events failed, either \ - an event could not be found or deserialization" + an event could not be found or deserialization" ); None } @@ -872,7 +873,7 @@ impl Service { state_at_incoming_event = Some(state); } Err(error) => { - t::warn!(%error, "Fetching state for event failed"); + warn_err!(error, "Fetching state for event failed"); return Err(error); } }; @@ -1169,7 +1170,7 @@ impl Service { let fetch_event = |id: &_| { let res = services().rooms.timeline.get_pdu(id); if let Err(error) = &res { - t::error!(%error, "Failed to fetch event"); + error_err!(error, "Failed to fetch event"); } res.ok().flatten() }; @@ -1415,9 +1416,9 @@ impl Service { } } Err(error) => { - t::warn!( + warn_err!( + error, event_id = %next_id, - %error, "Event failed auth checks", ); back_off((**next_id).to_owned()).await; @@ -1598,7 +1599,7 @@ impl Service { ) -> Result<()> { let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) .map_err(|error| { - t::error!(%error, ?pdu, "Invalid PDU in server response"); + error_err!(error, ?pdu, "Invalid PDU in server response"); Error::BadServerResponse("Invalid PDU in server response") })?; @@ -1739,7 +1740,7 @@ impl Service { ) .await { - t::debug!(%error, "Failed to get server keys from cache"); + debug_err!(error, "Failed to get server keys from cache"); }; } @@ -1769,8 +1770,8 @@ impl Service { let k = match k.deserialize() { Ok(key) => key, Err(error) => { - t::warn!( - %error, + warn_err!( + error, %server, object = ?k.json(), "Failed to fetch keys from trusted server", @@ -1861,7 +1862,7 @@ impl Service { { Ok(x) => x, Err(error) => { - t::warn!(%error, "Invalid ACL event"); + warn_err!(error, "Invalid ACL event"); return Ok(()); } }; diff --git a/src/service/rooms/spaces.rs b/src/service/rooms/spaces.rs index 16ad90e8..8820dfde 100644 --- a/src/service/rooms/spaces.rs +++ b/src/service/rooms/spaces.rs @@ -184,8 +184,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomJoinRulesEventContent| c.join_rule) .map_err(|error| { - t::error!( - %error, + error_err!( + error, "Invalid room join rule event" ); Error::BadDatabase( @@ -352,8 +352,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomCanonicalAliasEventContent| c.alias) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room canonical alias event" ); @@ -382,8 +382,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomTopicEventContent| Some(c.topic)) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room topic event" ); @@ -407,8 +407,8 @@ impl Service { == HistoryVisibility::WorldReadable }) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room history visibility event" ); @@ -428,8 +428,8 @@ impl Service { c.guest_access == GuestAccess::CanJoin }) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room guest access event" ); @@ -446,8 +446,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomAvatarEventContent| c.url) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room avatar event" ); @@ -471,8 +471,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomJoinRulesEventContent| c.join_rule) .map_err(|error| { - t::error!( - %error, + error_err!( + error, event_id = %s.event_id, "Invalid room join rule event", ); diff --git a/src/service/rooms/state.rs b/src/service/rooms/state.rs index cc8a5889..13deb35a 100644 --- a/src/service/rooms/state.rs +++ b/src/service/rooms/state.rs @@ -381,7 +381,7 @@ impl Service { .map(|create_event| { serde_json::from_str::(create_event.content.get()).map_err( |error| { - t::warn!(%error, "Invalid create event"); + warn_err!(error, "Invalid create event"); Error::BadDatabase("Invalid create event in db.") }, ) diff --git a/src/service/rooms/state_accessor.rs b/src/service/rooms/state_accessor.rs index 6616e361..0ae2f885 100644 --- a/src/service/rooms/state_accessor.rs +++ b/src/service/rooms/state_accessor.rs @@ -496,8 +496,8 @@ impl Service { serde_json::from_str(s.content.get()) .map(|c: RoomNameEventContent| Some(c.name)) .map_err(|error| { - t::error!( - %error, + error_err!( + error, "Invalid room name event in database" ); Error::BadDatabase( diff --git a/src/service/rooms/state_cache.rs b/src/service/rooms/state_cache.rs index 69797a76..72ad931d 100644 --- a/src/service/rooms/state_cache.rs +++ b/src/service/rooms/state_cache.rs @@ -75,7 +75,7 @@ impl Service { .state .get_create_content::(room_id) .inspect_err(|error| { - t::warn!(%error, "Failed to get room predecessor"); + warn_err!(error, "Failed to get room predecessor"); }) .ok() .flatten() @@ -110,8 +110,8 @@ impl Service { event.get(), ) .map_err(|error| { - t::warn!( - %error, + warn_err!( + error, %event_kind, "Invalid account data event", ); @@ -215,8 +215,8 @@ impl Service { RoomAccountDataEventType::Tag, &event, ) { - t::warn!( - %error, + warn_err!( + error, "error writing m.tag account data to upgraded room" ); } @@ -293,9 +293,9 @@ impl Service { event_kind.clone(), &event, ) { - t::warn!( + warn_err!( + error, %event_kind, - %error, "error writing account data event after upgrading room" ); } diff --git a/src/service/rooms/timeline.rs b/src/service/rooms/timeline.rs index ada3fd3a..88dbd2d0 100644 --- a/src/service/rooms/timeline.rs +++ b/src/service/rooms/timeline.rs @@ -161,7 +161,7 @@ impl Service { .find_map(|x| match x { Ok(x) => Some(x), Err(error) => { - t::error!(%error, "Bad pdu in pdus_since"); + error_err!(error, "Bad pdu in pdus_since"); None } }) @@ -879,7 +879,7 @@ impl Service { |k, s| auth_events.get(&(k.clone(), s.to_owned())), ) .map_err(|error| { - t::error!(%error, "Auth check failed"); + error_err!(error, "Auth check failed"); Error::BadDatabase("Auth check failed.") })?; @@ -1340,15 +1340,15 @@ impl Service { .backfill_pdu(backfill_server, pdu, &pub_key_map) .await { - t::warn!(%error, "Failed to add backfilled pdu"); + warn_err!(error, "Failed to add backfilled pdu"); } } return Ok(()); } Err(error) => { - t::warn!( + warn_err!( + error, server = %backfill_server, - %error, "Server could not provide backfill", ); } diff --git a/src/service/sending.rs b/src/service/sending.rs index de4dadfe..19b4d376 100644 --- a/src/service/sending.rs +++ b/src/service/sending.rs @@ -267,7 +267,7 @@ impl Service { } if let Err(error) = result { - t::warn!(%error, "Marking transaction as failed"); + warn_err!(error, "Marking transaction as failed"); current_transaction_status.entry(destination).and_modify(|e| { use TransactionStatus::{Failed, Retrying, Running}; @@ -354,7 +354,7 @@ impl Service { None } Err(error) => { - t::error!(%error, "Failed to select events to send"); + error_err!(error, "Failed to select events to send"); None } } diff --git a/src/utils/on_demand_hashmap.rs b/src/utils/on_demand_hashmap.rs index 8275e8db..aa4494ef 100644 --- a/src/utils/on_demand_hashmap.rs +++ b/src/utils/on_demand_hashmap.rs @@ -199,7 +199,7 @@ impl Drop for EntryDropGuard { if let Err(error) = cleanup_sender .send(self.key.take().expect("drop should only be called once")) { - t::warn!(%error, "Failed to send cleanup message"); + warn_err!(error, "Failed to send cleanup message"); }; } } diff --git a/src/utils/proxy_protocol.rs b/src/utils/proxy_protocol.rs index 5e260f6c..278b3cb6 100644 --- a/src/utils/proxy_protocol.rs +++ b/src/utils/proxy_protocol.rs @@ -145,8 +145,8 @@ where std::io::Error::new(ErrorKind::TimedOut, e) })? .inspect_err(|error| { - t::warn!( - %error, + warn_err!( + error, "Failed to parse HAProxy protocol header" ); })?; From a2628357fd73bf01cef2f2e6326d132153214e3f Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 02:23:46 -0800 Subject: [PATCH 06/12] show source chain in error response message Error messages in logs should generally be similar to the messages in the response body now. There's a bit of a concern with the source chain leaking sensitive information, but the errors that had a source were generally already logging the second error in the chain in their own Display impl, so if this is a problem it's unlikely to be a regression. --- src/utils/error.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/utils/error.rs b/src/utils/error.rs index d855d737..53593f73 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -9,6 +9,7 @@ use ruma::{ OwnedServerName, }; use thiserror::Error; +use wee_woo::ErrorExt; use crate::{observability::prelude::*, Ra}; @@ -117,7 +118,7 @@ impl Error { return Ra(UiaaResponse::MatrixError(error)); } - let message = format!("{self}"); + let message = format!("{}", self.display_with_sources(" -> ")); let (kind, status_code) = match self { Self::BadRequest(kind, _) => ( From ed7f7b246195e508924c36de5cdcb1ba8f57f891 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 15:52:13 -0800 Subject: [PATCH 07/12] rename Error::Conflict to Error::AliasConflict This is only used in one place. --- src/api/client_server/alias.rs | 2 +- src/utils/error.rs | 7 +++---- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/api/client_server/alias.rs b/src/api/client_server/alias.rs index b2fbcf65..12768509 100644 --- a/src/api/client_server/alias.rs +++ b/src/api/client_server/alias.rs @@ -44,7 +44,7 @@ pub(crate) async fn create_alias_route( } if services().rooms.alias.resolve_local_alias(&body.room_alias)?.is_some() { - return Err(Error::Conflict("Alias already exists.")); + return Err(Error::AliasConflict); } services().rooms.alias.set_alias( diff --git a/src/utils/error.rs b/src/utils/error.rs index 53593f73..5dcb667e 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -69,9 +69,8 @@ pub(crate) enum Error { Uiaa(UiaaInfo), #[error("{0}: {1}")] BadRequest(ErrorKind, &'static str), - // This is only needed for when a room alias already exists - #[error("{0}")] - Conflict(&'static str), + #[error("alias already exists")] + AliasConflict, #[error("{0}")] Extension(#[from] axum::extract::rejection::ExtensionRejection), #[error("{0}")] @@ -152,7 +151,7 @@ impl Error { ErrorKind::UnsupportedRoomVersion, StatusCode::INTERNAL_SERVER_ERROR, ), - Self::Conflict(_) => (Unknown, StatusCode::CONFLICT), + Self::AliasConflict => (Unknown, StatusCode::CONFLICT), _ => (Unknown, StatusCode::INTERNAL_SERVER_ERROR), }; From 05043f97a039836a9783d0451ba031c6f91edd13 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 15:59:45 -0800 Subject: [PATCH 08/12] rename Error::Image to Error::GenerateThumbnail The previous error was nonspecific and, because of the '#[from]' annotation, could have been used accidentally for *any* errors from the image crate. --- src/service/media.rs | 10 ++++++---- src/utils/error.rs | 7 ++----- 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/src/service/media.rs b/src/service/media.rs index 84e5664c..cc0aded3 100644 --- a/src/service/media.rs +++ b/src/service/media.rs @@ -276,10 +276,12 @@ impl Service { t::debug!("Serializing thumbnail as PNG"); let mut thumbnail_bytes = Vec::new(); - thumbnail.write_to( - &mut Cursor::new(&mut thumbnail_bytes), - image::ImageFormat::Png, - )?; + thumbnail + .write_to( + &mut Cursor::new(&mut thumbnail_bytes), + image::ImageFormat::Png, + ) + .map_err(Error::GenerateThumbnail)?; Ok(Some(thumbnail_bytes)) } diff --git a/src/utils/error.rs b/src/utils/error.rs index 5dcb667e..db0735c4 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -36,11 +36,8 @@ pub(crate) enum Error { #[from] source: rocksdb::Error, }, - #[error("Could not generate an image.")] - Image { - #[from] - source: image::error::ImageError, - }, + #[error("Could not generate image thumbnail.")] + GenerateThumbnail(#[source] image::error::ImageError), #[error("Could not connect to server: {source}")] Reqwest { #[from] From 45be146c14b277dde832c6e5ca4bedfccb71abdf Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 02:23:32 -0800 Subject: [PATCH 09/12] rewrite all the error display strings Now that we log the source chain, there is no need to format the source error in display. Also, a lot of these were terrible for other reasons. --- src/utils/error.rs | 36 +++++++++++++++--------------------- 1 file changed, 15 insertions(+), 21 deletions(-) diff --git a/src/utils/error.rs b/src/utils/error.rs index db0735c4..980373b9 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -19,52 +19,46 @@ pub(crate) type Result = std::result::Result; #[allow(clippy::error_impl_error)] pub(crate) enum Error { #[cfg(feature = "sqlite")] - #[error( - "There was a problem with the connection to the sqlite database: \ - {source}" - )] + #[error("error connecting to sqlite database")] Sqlite { #[from] source: rusqlite::Error, }, #[cfg(feature = "rocksdb")] - #[error( - "There was a problem with the connection to the rocksdb database: \ - {source}" - )] + #[error("error connecting to rocksdb database")] RocksDb { #[from] source: rocksdb::Error, }, - #[error("Could not generate image thumbnail.")] + #[error("error generating image thumbnail")] GenerateThumbnail(#[source] image::error::ImageError), - #[error("Could not connect to server: {source}")] + #[error("error making request to server")] Reqwest { #[from] source: reqwest::Error, }, - #[error("Could build regular expression: {source}")] + #[error("error building regular expression")] Regex { #[from] source: regex::Error, }, - #[error("{0}")] - Federation(OwnedServerName, RumaError), - #[error("Could not do this io: {source}")] + #[error("federation request to {0} returned an error")] + Federation(OwnedServerName, #[source] RumaError), + #[error("IO error")] Io { #[from] source: std::io::Error, }, - #[error("{0}")] + #[error("invalid server response: {0}")] BadServerResponse(&'static str), - #[error("{0}")] + #[error("config error: {0}")] BadConfig(&'static str), - #[error("{0}")] + #[error("invalid data in database: {0}")] /// Don't create this directly. Use [`Error::bad_database`] instead. BadDatabase(&'static str), - #[error("uiaa")] + #[error("UIAA error")] Uiaa(UiaaInfo), - #[error("{0}: {1}")] + #[error("invalid request ({0}): {1}")] BadRequest(ErrorKind, &'static str), #[error("alias already exists")] AliasConflict, @@ -74,11 +68,11 @@ pub(crate) enum Error { Path(#[from] axum::extract::rejection::PathRejection), #[error("{0}")] AdminCommand(&'static str), - #[error("from {0}: {1}")] + #[error("error redacting event from {0}: {1}")] Redaction(OwnedServerName, ruma::canonical_json::RedactionError), #[error("unsupported room version {0}")] UnsupportedRoomVersion(ruma::RoomVersionId), - #[error("{0} in {1}")] + #[error("inconsistent room state in {1}: {0}")] InconsistentRoomState(&'static str, ruma::OwnedRoomId), } From 165ff0b50c5a9f5d34e4db729d7a2ea115e0e7f6 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 16:47:46 -0800 Subject: [PATCH 10/12] propagate error code from federation response errors Previously we were propagating the status code, but always returning M_UNKNOWN regardless of the remote error code. This seems kinda pointless, so just propagate both. We can also stop special-casing the message now that the display impl is reasonable. --- src/utils/error.rs | 14 +++++--------- 1 file changed, 5 insertions(+), 9 deletions(-) diff --git a/src/utils/error.rs b/src/utils/error.rs index 980373b9..833c72b8 100644 --- a/src/utils/error.rs +++ b/src/utils/error.rs @@ -99,15 +99,6 @@ impl Error { return Ra(UiaaResponse::AuthResponse(uiaainfo.clone())); } - if let Self::Federation(origin, error) = self { - let mut error = error.clone(); - error.body = ErrorBody::Standard { - kind: Unknown, - message: format!("Answer from {origin}: {error}"), - }; - return Ra(UiaaResponse::MatrixError(error)); - } - let message = format!("{}", self.display_with_sources(" -> ")); let (kind, status_code) = match self { @@ -138,6 +129,11 @@ impl Error { _ => StatusCode::BAD_REQUEST, }, ), + // Propagate the status code and error code from the remote response + Self::Federation(_, error) => ( + error.error_kind().cloned().unwrap_or(Unknown), + error.status_code, + ), Self::UnsupportedRoomVersion(_) => ( ErrorKind::UnsupportedRoomVersion, StatusCode::INTERNAL_SERVER_ERROR, From 414feb045530203168c764e43dd6bb14d6ff3049 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 18:05:53 -0800 Subject: [PATCH 11/12] update style guide for new logging style --- book/contributing/style-guide.md | 36 ++++++++++++++++++++++++++------ 1 file changed, 30 insertions(+), 6 deletions(-) diff --git a/book/contributing/style-guide.md b/book/contributing/style-guide.md index 957a13a1..a380bf90 100644 --- a/book/contributing/style-guide.md +++ b/book/contributing/style-guide.md @@ -89,6 +89,13 @@ in mind. Especially, keeping Cargo unit tests in a dedicated tests file ## Tracing +Modules that emit tracing events should import +`crate::observability::prelude::*`, which re-exports `tracing` as `t`, instead +of importing tracing macros directly and using them without a path. + +**Why?** Avoiding name collisions and diff churn, since the set of tracing +macros used by a module tends to change frequently. + `tracing` events should: 1. Start with a capital letter (when applicable). @@ -102,26 +109,33 @@ in mind. Especially, keeping Cargo unit tests in a dedicated tests file **Why?** Consistency is good. Also, interpolating values into the event message essentially defeats the point of structured logging. +When emitting tracing events containing errors, use the `_err!` macros +from `observability::prelude` instead of `t::!`. + +**Why?** This will log the full source chain instead of just the `Display` impl +of the first error in the chain, making it easier to identify the cause of +errors in thelogs. + ### Examples #### 1 ```rust,ignore // This does not conform because it does not start with a capital letter. -info!("started pentametric fan"); +t::info!("started pentametric fan"); // Do this instead: -info!("Started pentametric fan"); +t::info!("Started pentametric fan"); ``` #### 2 ```rust,ignore // This does not conform because it ends with punctuation. -info!("Started pentametric fan."); +t::info!("Started pentametric fan."); // Do this instead: -info!("Started pentametric fan"); +t::info!("Started pentametric fan"); ``` #### 3 @@ -129,10 +143,20 @@ info!("Started pentametric fan"); ```rust,ignore // This does not conform because it interpolates values into the event's // message. -warn!("Noticed {} discombobulated waneshafts", count); +t::warn!("Noticed {} discombobulated waneshafts", count); // Do this instead: -warn!(count, "Noticed discombobulated waneshafts"); +t::warn!(count, "Noticed discombobulated waneshafts"); +``` + +#### 4 + +```rust,ignore +// This does not conform because it logs only the first error in the chain +t::error!(%error, "Failed to automatically synchronize cardinal grammeters"); + +// Do this instead: +error_err!(error, "Failed to automatically synchronize cardinal grammeters"); ``` ## Services From ca37f150b6111b429641e9a07ebcffd16dc09e0e Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 18:06:46 -0800 Subject: [PATCH 12/12] add error refactors to the changelog --- book/changelog.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/book/changelog.md b/book/changelog.md index 0a233597..c1f301ad 100644 --- a/book/changelog.md +++ b/book/changelog.md @@ -116,7 +116,8 @@ This will be the first release of Grapevine since it was forked from Conduit [!69](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/69), [!102](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/102), [!127](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/127), - [!141](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/141)) + [!141](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/141), + [!155](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/155)) 4. Stop returning unnecessary member counts from `/_matrix/client/{r0,v3}/sync`. ([!12](https://gitlab.computer.surgery/matrix/grapevine/-/merge_requests/12)) 5. **BREAKING:** Allow federation by default.