From 5fca67054e8ab049bd3dd315e5b6ade62fd62bf2 Mon Sep 17 00:00:00 2001 From: Olivia Lee Date: Sat, 14 Dec 2024 00:49:56 -0800 Subject: [PATCH] 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 =