More useful tracing spans

src/service/admin.rs

@@ -38,11 +38,12 @@ use tracing::warn;
 use super::pdu::PduBuilder;
 use crate::{
     api::client_server::{leave_all_rooms, AUTO_GEN_PASSWORD_LENGTH},
-    services, utils, Error, PduEvent, Result,
+    services,
+    utils::{self, truncate_str_for_debug},
+    Error, PduEvent, Result,
 };
 
-#[cfg_attr(test, derive(Debug))]
+#[derive(Debug, Parser)]
-#[derive(Parser)]
 #[command(name = "@grapevine:server.name:", version = env!("CARGO_PKG_VERSION"))]
 enum AdminCommand {
     #[command(verbatim_doc_comment)]
@@ -298,10 +299,17 @@ impl Service {
             .unwrap();
     }
 
+    #[tracing::instrument(
+        skip(self, room_message),
+        fields(
+            room_message = truncate_str_for_debug(&room_message, 50).as_ref(),
+        ),
+    )]
     pub(crate) fn process_message(&self, room_message: String) {
         self.sender.send(AdminRoomEvent::ProcessMessage(room_message)).unwrap();
     }
 
+    #[tracing::instrument(skip(self, message_content))]
     pub(crate) fn send_message(
         &self,
         message_content: RoomMessageEventContent,
@@ -310,6 +318,12 @@ impl Service {
     }
 
     // Parse and process a message from the admin room
+    #[tracing::instrument(
+        skip(self, room_message),
+        fields(
+            room_message = truncate_str_for_debug(&room_message, 50).as_ref(),
+        ),
+    )]
     async fn process_admin_message(
         &self,
         room_message: String,
@@ -355,6 +369,12 @@ impl Service {
     }
 
     // Parse chat messages from the admin room into an AdminCommand object
+    #[tracing::instrument(
+        skip(command_line),
+        fields(
+            command_line = truncate_str_for_debug(command_line, 50).as_ref(),
+        ),
+    )]
     fn parse_admin_command(
         command_line: &str,
     ) -> std::result::Result<AdminCommand, String> {
@@ -380,6 +400,7 @@ impl Service {
     }
 
     #[allow(clippy::too_many_lines)]
+    #[tracing::instrument(skip(self, body))]
     async fn process_admin_command(
         &self,
         command: AdminCommand,
@@ -1067,6 +1088,7 @@ impl Service {
     }
 
     // Utility to turn clap's `--help` text to HTML.
+    #[tracing::instrument(skip_all)]
     fn usage_to_html(text: &str, server_name: &ServerName) -> String {
         // Replace `@grapevine:servername:-subcmdname` with
         // `@grapevine:servername: subcmdname`
@@ -1151,6 +1173,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))]
     pub(crate) async fn create_admin_room(&self) -> Result<()> {
         let room_id = RoomId::new(services().globals.server_name());
 
@@ -1435,6 +1458,7 @@ impl Service {
     /// Invite the user to the grapevine admin room.
     ///
     /// In grapevine, this is equivalent to granting admin privileges.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn make_user_admin(
         &self,
         user_id: &UserId,

src/service/appservice.rs

@@ -136,6 +136,7 @@ impl Service {
     }
 
     /// Registers an appservice and returns the ID to the caller.
+    #[tracing::instrument(skip(self, yaml), fields(appservice_id = yaml.id))]
     pub(crate) async fn register_appservice(
         &self,
         yaml: Registration,
@@ -154,6 +155,7 @@ impl Service {
     /// # Arguments
     ///
     /// * `service_name` - the name you send to register the service previously
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn unregister_appservice(
         &self,
         service_name: &str,
@@ -171,6 +173,7 @@ impl Service {
         self.db.unregister_appservice(service_name)
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn get_registration(
         &self,
         id: &str,
@@ -187,6 +190,7 @@ impl Service {
         self.registration_info.read().await.keys().cloned().collect()
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn find_from_token(
         &self,
         token: &str,
@@ -199,6 +203,7 @@ impl Service {
     }
 
     // Checks if a given user id matches any exclusive appservice regex
+    #[tracing::instrument(skip(self), ret(level = "trace"))]
     pub(crate) async fn is_exclusive_user_id(&self, user_id: &UserId) -> bool {
         self.read()
             .await
@@ -207,6 +212,7 @@ impl Service {
     }
 
     // Checks if a given room alias matches any exclusive appservice regex
+    #[tracing::instrument(skip(self), ret(level = "trace"))]
     pub(crate) async fn is_exclusive_alias(&self, alias: &RoomAliasId) -> bool {
         self.read()
             .await

src/service/globals.rs

@@ -29,7 +29,7 @@ use ruma::{
     OwnedServerSigningKeyId, RoomVersionId, ServerName, UserId,
 };
 use tokio::sync::{broadcast, Mutex, RwLock, Semaphore};
-use tracing::{error, info};
+use tracing::{error, info, Instrument};
 use trust_dns_resolver::TokioAsyncResolver;
 
 use crate::{api::server_server::FedDest, services, Config, Error, Result};
@@ -126,6 +126,7 @@ impl Resolver {
 }
 
 impl Resolve for Resolver {
+    #[tracing::instrument(skip(self))]
     fn resolve(&self, name: Name) -> Resolving {
         self.overrides
             .read()
@@ -144,18 +145,25 @@ impl Resolve for Resolver {
             })
             .unwrap_or_else(|| {
                 let this = &mut self.inner.clone();
-                Box::pin(HyperService::<Name>::call(this, name).map(|result| {
+                Box::pin(
-                    result.map(|addrs| -> Addrs { Box::new(addrs) }).map_err(
+                    HyperService::<Name>::call(this, name)
-                        |err| -> Box<dyn StdError + Send + Sync> {
+                        .map(|result| {
-                            Box::new(err)
+                            result
-                        },
+                                .map(|addrs| -> Addrs { Box::new(addrs) })
-                    )
+                                .map_err(
-                }))
+                                    |err| -> Box<dyn StdError + Send + Sync> {
+                                        Box::new(err)
+                                    },
+                                )
+                        })
+                        .in_current_span(),
+                )
             })
     }
 }
 
 impl Service {
+    #[tracing::instrument(skip_all)]
     pub(crate) fn load(db: &'static dyn Data, config: Config) -> Result<Self> {
         let keypair = db.load_keypair();
 

src/service/media.rs

@@ -30,6 +30,7 @@ pub(crate) struct Service {
 
 impl Service {
     /// Uploads a file.
+    #[tracing::instrument(skip(self, file))]
     pub(crate) async fn create(
         &self,
         mxc: String,
@@ -54,6 +55,7 @@ impl Service {
 
     /// Uploads or replaces a file thumbnail.
     #[allow(clippy::too_many_arguments)]
+    #[tracing::instrument(skip(self, file))]
     pub(crate) async fn upload_thumbnail(
         &self,
         mxc: String,
@@ -79,6 +81,7 @@ impl Service {
     }
 
     /// Downloads a file.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn get(&self, mxc: String) -> Result<Option<FileMeta>> {
         if let Ok((content_disposition, content_type, key)) =
             self.db.search_file_metadata(mxc, 0, 0)
@@ -129,6 +132,7 @@ impl Service {
     /// For width,height <= 96 the server uses another thumbnailing algorithm
     /// which crops the image afterwards.
     #[allow(clippy::too_many_lines)]
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn get_thumbnail(
         &self,
         mxc: String,

src/service/pdu.rs

@@ -351,7 +351,7 @@ impl PduEvent {
     }
 
     /// This does not return a full `Pdu` it is only to satisfy ruma's types.
-    #[tracing::instrument]
+    #[tracing::instrument(skip(pdu_json))]
     pub(crate) fn convert_to_outgoing_federation_event(
         mut pdu_json: CanonicalJsonObject,
     ) -> Box<RawJsonValue> {

src/service/rooms/auth_chain.rs

@@ -8,7 +8,7 @@ pub(crate) use data::Data;
 use ruma::{api::client::error::ErrorKind, EventId, RoomId};
 use tracing::{debug, error, warn};
 
-use crate::{services, Error, Result};
+use crate::{services, utils::debug_slice_truncated, Error, Result};
 
 pub(crate) struct Service {
     pub(crate) db: &'static dyn Data,
@@ -31,7 +31,10 @@ impl Service {
         self.db.cache_auth_chain(key, auth_chain)
     }
 
-    #[tracing::instrument(skip(self, starting_events))]
+    #[tracing::instrument(
+        skip(self, starting_events),
+        fields(starting_events = debug_slice_truncated(&starting_events, 5)),
+    )]
     pub(crate) async fn get_auth_chain<'a>(
         &self,
         room_id: &RoomId,
@@ -138,7 +141,7 @@ impl Service {
         }))
     }
 
-    #[tracing::instrument(skip(self, event_id))]
+    #[tracing::instrument(skip(self))]
     fn get_auth_chain_inner(
         &self,
         room_id: &RoomId,

src/service/rooms/edus/typing.rs

@@ -21,6 +21,7 @@ pub(crate) struct Service {
 impl Service {
     /// Sets a user as typing until the timeout timestamp is reached or
     /// `roomtyping_remove` is called.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn typing_add(
         &self,
         user_id: &UserId,
@@ -47,6 +48,7 @@ impl Service {
     }
 
     /// Removes a user from typing before the timeout is reached.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn typing_remove(
         &self,
         user_id: &UserId,
@@ -71,6 +73,7 @@ impl Service {
         Ok(())
     }
 
+    #[tracing::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 {
@@ -83,6 +86,7 @@ impl Service {
     }
 
     /// Makes sure that typing events with old timestamps get removed.
+    #[tracing::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();
@@ -119,6 +123,7 @@ impl Service {
     }
 
     /// Returns the count of the last typing update in this room.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn last_typing_update(
         &self,
         room_id: &RoomId,
@@ -134,6 +139,7 @@ impl Service {
     }
 
     /// Returns a new typing EDU.
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn typings_all(
         &self,
         room_id: &RoomId,

src/service/rooms/event_handler.rs

@@ -1085,6 +1085,7 @@ impl Service {
         Ok(pdu_id)
     }
 
+    #[tracing::instrument(skip(self, room_version_id, incoming_state))]
     async fn resolve_state(
         &self,
         room_id: &RoomId,
@@ -1397,6 +1398,8 @@ impl Service {
         })
     }
 
+    #[tracing::instrument(skip_all)]
+    #[allow(clippy::type_complexity)]
     async fn fetch_unknown_prev_events(
         &self,
         origin: &ServerName,
@@ -1558,6 +1561,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)]
     async fn get_server_keys_from_cache(
         &self,
         pdu: &RawJsonValue,
@@ -1797,6 +1801,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)]
     pub(crate) fn acl_check(
         &self,
         server_name: &ServerName,
@@ -2010,6 +2015,7 @@ impl Service {
         Err(Error::BadServerResponse("Failed to find public key for server"))
     }
 
+    #[tracing::instrument(skip_all)]
     fn check_room_id(room_id: &RoomId, pdu: &PduEvent) -> Result<()> {
         if pdu.room_id != room_id {
             warn!("Found event from room {} in room {}", pdu.room_id, room_id);

src/service/rooms/pdu_metadata.rs

@@ -51,6 +51,7 @@ impl Service {
         // Allowed because this function uses `services()`
         clippy::unused_self,
     )]
+    #[tracing::instrument(skip(self))]
     pub(crate) fn paginate_relations_with_filter(
         &self,
         sender_user: &UserId,
@@ -178,6 +179,7 @@ impl Service {
         }
     }
 
+    #[tracing::instrument(skip_all)]
     pub(crate) fn relations_until<'a>(
         &'a self,
         user_id: &'a UserId,

src/service/rooms/spaces.rs

@@ -51,6 +51,7 @@ pub(crate) struct Service {
 
 impl Service {
     #[allow(clippy::too_many_lines)]
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn get_hierarchy(
         &self,
         sender_user: &UserId,
@@ -326,6 +327,7 @@ impl Service {
     }
 
     #[allow(clippy::too_many_lines)]
+    #[tracing::instrument(skip(self, sender_user, children))]
     fn get_room_chunk(
         &self,
         sender_user: &UserId,
@@ -525,6 +527,7 @@ impl Service {
         Ok(allowed)
     }
 
+    #[tracing::instrument(skip(self, sender_user))]
     fn handle_join_rule(
         &self,
         join_rule: &JoinRule,

src/service/rooms/state.rs

@@ -20,7 +20,11 @@ use tokio::sync::MutexGuard;
 use tracing::warn;
 
 use super::state_compressor::CompressedStateEvent;
-use crate::{services, utils::calculate_hash, Error, PduEvent, Result};
+use crate::{
+    services,
+    utils::{calculate_hash, debug_slice_truncated},
+    Error, PduEvent, Result,
+};
 
 pub(crate) struct Service {
     pub(crate) db: &'static dyn Data,
@@ -28,6 +32,12 @@ pub(crate) struct Service {
 
 impl Service {
     /// Set the room to the given statehash and update caches.
+    #[tracing::instrument(skip(
+        self,
+        statediffnew,
+        _statediffremoved,
+        state_lock
+    ))]
     pub(crate) async fn force_state(
         &self,
         room_id: &RoomId,
@@ -354,6 +364,7 @@ impl Service {
         Ok(create_event_content.room_version)
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) fn get_room_shortstatehash(
         &self,
         room_id: &RoomId,
@@ -361,6 +372,7 @@ impl Service {
         self.db.get_room_shortstatehash(room_id)
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) fn get_forward_extremities(
         &self,
         room_id: &RoomId,
@@ -368,6 +380,10 @@ impl Service {
         self.db.get_forward_extremities(room_id)
     }
 
+    #[tracing::instrument(
+        skip(self, event_ids, state_lock),
+        fields(event_ids = debug_slice_truncated(&event_ids, 5)),
+    )]
     pub(crate) fn set_forward_extremities(
         &self,
         room_id: &RoomId,

src/service/rooms/state_accessor.rs

@@ -47,6 +47,7 @@ impl Service {
         self.db.state_full_ids(shortstatehash).await
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) async fn state_full(
         &self,
         shortstatehash: u64,
@@ -68,6 +69,7 @@ impl Service {
 
     /// Returns a single PDU from `room_id` with key (`event_type`,
     /// `state_key`).
+    #[tracing::instrument(skip(self))]
     pub(crate) fn state_get(
         &self,
         shortstatehash: u64,
@@ -78,6 +80,7 @@ impl Service {
     }
 
     /// Get membership for given user in state
+    #[tracing::instrument(skip(self))]
     fn user_membership(
         &self,
         shortstatehash: u64,
@@ -100,6 +103,7 @@ impl Service {
     }
 
     /// The user was a joined member at this state (potentially in the past)
+    #[tracing::instrument(skip(self), ret(level = "trace"))]
     fn user_was_joined(&self, shortstatehash: u64, user_id: &UserId) -> bool {
         self.user_membership(shortstatehash, user_id)
             .map(|s| s == MembershipState::Join)
@@ -108,6 +112,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"))]
     fn user_was_invited(&self, shortstatehash: u64, user_id: &UserId) -> bool {
         self.user_membership(shortstatehash, user_id)
             .map(|s| s == MembershipState::Join || s == MembershipState::Invite)
@@ -294,6 +299,7 @@ impl Service {
     }
 
     /// Returns the state hash for this pdu.
+    #[tracing::instrument(skip(self))]
     pub(crate) fn pdu_shortstatehash(
         &self,
         event_id: &EventId,
@@ -334,6 +340,7 @@ impl Service {
         self.db.room_state_get(room_id, event_type, state_key)
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) fn get_name(&self, room_id: &RoomId) -> Result<Option<String>> {
         self.room_state_get(room_id, &StateEventType::RoomName, "")?.map_or(
             Ok(None),
@@ -354,6 +361,7 @@ impl Service {
         )
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) fn get_avatar(
         &self,
         room_id: &RoomId,
@@ -372,6 +380,7 @@ impl Service {
 
     // Allowed because this function uses `services()`
     #[allow(clippy::unused_self)]
+    #[tracing::instrument(skip(self), ret(level = "trace"))]
     pub(crate) fn user_can_invite(
         &self,
         room_id: &RoomId,
@@ -398,6 +407,7 @@ impl Service {
             .is_ok()
     }
 
+    #[tracing::instrument(skip(self))]
     pub(crate) fn get_member(
         &self,
         room_id: &RoomId,
@@ -420,6 +430,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))]
     pub(crate) fn user_can_redact(
         &self,
         redacts: &EventId,

src/service/rooms/state_compressor.rs

@@ -286,6 +286,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))]
     pub(crate) fn save_state(
         &self,
         room_id: &RoomId,

src/service/sending.rs

@@ -40,7 +40,7 @@ use tracing::{debug, error, warn};
 use crate::{
     api::{appservice_server, server_server},
     services,
-    utils::calculate_hash,
+    utils::{calculate_hash, debug_slice_truncated},
     Config, Error, PduEvent, Result,
 };
 
@@ -301,12 +301,13 @@ impl Service {
         }
     }
 
-    #[tracing::instrument(skip(
+    #[tracing::instrument(
-        self,
+        skip(self, new_events, current_transaction_status),
-        outgoing_kind,
+        fields(
-        new_events,
+            new_events = debug_slice_truncated(&new_events, 3),
-        current_transaction_status
+            current_status = ?current_transaction_status.get(outgoing_kind),
-    ))]
+        ),
+    )]
     fn select_events(
         &self,
         outgoing_kind: &OutgoingKind,
@@ -386,7 +387,7 @@ impl Service {
         Ok(Some(events))
     }
 
-    #[tracing::instrument(skip(self, server_name))]
+    #[tracing::instrument(skip(self))]
     pub(crate) fn select_edus(
         &self,
         server_name: &ServerName,
@@ -598,7 +599,7 @@ impl Service {
         Ok(())
     }
 
-    #[tracing::instrument(skip(events, kind))]
+    #[tracing::instrument(skip(events))]
     async fn handle_events(
         kind: OutgoingKind,
         events: Vec<SendingEventType>,
@@ -876,7 +877,7 @@ impl Service {
         }
     }
 
-    #[tracing::instrument(skip(self, destination, request))]
+    #[tracing::instrument(skip(self, request))]
     pub(crate) async fn send_federation_request<T: OutgoingRequest>(
         &self,
         destination: &ServerName,
@@ -906,7 +907,10 @@ impl Service {
     ///
     /// Only returns None if there is no url specified in the appservice
     /// registration file
-    #[tracing::instrument(skip(self, registration, request))]
+    #[tracing::instrument(
+        skip(self, registration, request),
+        fields(appservice_id = registration.id),
+    )]
     pub(crate) async fn send_appservice_request<T: OutgoingRequest>(
         &self,
         registration: Registration,