additional tracing span tweaks

Signed-off-by: Jason Volk <jason@zemos.net>

src/api/server/send.rs

@@ -39,7 +39,15 @@ type ResolvedMap = BTreeMap<OwnedEventId, Result<()>>;
 /// # `PUT /_matrix/federation/v1/send/{txnId}`
 ///
 /// Push EDUs and PDUs to this server.
-#[tracing::instrument(skip_all, fields(%client, origin = body.origin().as_str()), name = "send")]
+#[tracing::instrument(
+	name = "send",
+	level = "debug",
+	skip_all,
+	fields(
+		%client,
+		origin = body.origin().as_str()
+	),
+)]
 pub(crate) async fn send_transaction_message_route(
 	State(services): State<crate::State>,
 	InsecureClientIp(client): InsecureClientIp,

src/database/pool.rs

@@ -12,7 +12,7 @@ use std::{
 
 use async_channel::{QueueStrategy, Receiver, RecvError, Sender};
 use conduwuit::{
-	debug, debug_warn, defer, err, error, implement,
+	debug, debug_warn, err, error, implement,
 	result::DebugInspect,
 	trace,
 	utils::sys::compute::{get_affinity, nth_core_available, set_affinity},
@@ -271,9 +271,6 @@ async fn execute(&self, queue: &Sender<Cmd>, cmd: Cmd) -> Result {
 	),
 )]
 fn worker(self: Arc<Self>, id: usize, recv: Receiver<Cmd>) {
-	defer! {{ trace!("worker finished"); }}
-	trace!("worker spawned");
-
 	self.worker_init(id);
 	self.worker_loop(&recv);
 }

src/service/rooms/auth_chain/mod.rs

@@ -79,7 +79,7 @@ impl Service {
 		Ok(event_ids)
 	}
 
-	#[tracing::instrument(skip_all, name = "auth_chain")]
+	#[tracing::instrument(name = "auth_chain", level = "debug", skip_all)]
 	pub async fn get_auth_chain<'a, I>(
 		&'a self,
 		room_id: &RoomId,
@@ -179,7 +179,7 @@ impl Service {
 		Ok(full_auth_chain)
 	}
 
-	#[tracing::instrument(skip(self, room_id))]
+	#[tracing::instrument(name = "inner", level = "trace", skip(self, room_id))]
 	async fn get_auth_chain_inner(
 		&self,
 		room_id: &RoomId,

src/service/rooms/event_handler/fetch_prev.rs

@@ -16,7 +16,7 @@ use super::check_room_id;
 
 #[implement(super::Service)]
 #[tracing::instrument(
-    level = "warn",
+    level = "debug",
 	skip_all,
 	fields(%origin),
 )]

src/service/rooms/event_handler/fetch_state.rs

@@ -14,7 +14,7 @@ use crate::rooms::short::ShortStateKey;
 /// on the events
 #[implement(super::Service)]
 #[tracing::instrument(
-	level = "warn",
+	level = "debug",
 	skip_all,
 	fields(%origin),
 )]

src/service/rooms/event_handler/handle_incoming_pdu.rs

@@ -41,7 +41,7 @@ use crate::rooms::timeline::RawPduId;
 #[implement(super::Service)]
 #[tracing::instrument(
 	name = "pdu",
-	level = "warn",
+	level = "debug",
 	skip_all,
 	fields(%room_id, %event_id),
 )]

src/service/rooms/event_handler/handle_prev_pdu.rs

@@ -14,7 +14,7 @@ use ruma::{CanonicalJsonValue, EventId, OwnedEventId, RoomId, ServerName};
 #[allow(clippy::too_many_arguments)]
 #[tracing::instrument(
 	name = "prev",
-	level = "warn",
+	level = "debug",
 	skip_all,
 	fields(%prev_id),
 )]

src/service/rooms/event_handler/resolve_state.rs

@@ -18,7 +18,7 @@ use ruma::{
 use crate::rooms::state_compressor::CompressedStateEvent;
 
 #[implement(super::Service)]
-#[tracing::instrument(skip_all, name = "resolve")]
+#[tracing::instrument(name = "resolve", level = "debug", skip_all)]
 pub async fn resolve_state(
 	&self,
 	room_id: &RoomId,

src/service/rooms/event_handler/state_at_incoming.rs

@@ -16,7 +16,7 @@ use ruma::{state_res::StateMap, OwnedEventId, RoomId, RoomVersionId};
 // TODO: if we know the prev_events of the incoming event we can avoid the
 #[implement(super::Service)]
 // request and build the state from a known point and resolve if > 1 prev_event
-#[tracing::instrument(skip_all, name = "state")]
+#[tracing::instrument(name = "state", level = "debug", skip_all)]
 pub(super) async fn state_at_incoming_degree_one(
 	&self,
 	incoming_pdu: &Arc<PduEvent>,
@@ -66,7 +66,7 @@ pub(super) async fn state_at_incoming_degree_one(
 }
 
 #[implement(super::Service)]
-#[tracing::instrument(skip_all, name = "state")]
+#[tracing::instrument(name = "state", level = "debug", skip_all)]
 pub(super) async fn state_at_incoming_resolved(
 	&self,
 	incoming_pdu: &Arc<PduEvent>,

src/service/rooms/state_compressor/mod.rs

@@ -7,7 +7,7 @@ use std::{
 
 use arrayvec::ArrayVec;
 use conduwuit::{
-	at, checked, debug, err, expected, utils,
+	at, checked, err, expected, utils,
 	utils::{bytes, math::usize_from_f64, stream::IterStream},
 	Result,
 };
@@ -117,35 +117,44 @@ impl crate::Service for Service {
 impl Service {
 	/// Returns a stack with info on shortstatehash, full state, added diff and
 	/// removed diff for the selected shortstatehash and each parent layer.
+	#[tracing::instrument(name = "load", level = "debug", skip(self))]
 	pub async fn load_shortstatehash_info(
 		&self,
 		shortstatehash: ShortStateHash,
 	) -> Result<ShortStateInfoVec> {
-		if let Some(r) = self
+		if let Some(r) = self.stateinfo_cache.lock()?.get_mut(&shortstatehash) {
-			.stateinfo_cache
-			.lock()
-			.expect("locked")
-			.get_mut(&shortstatehash)
-		{
 			return Ok(r.clone());
 		}
 
 		let stack = self.new_shortstatehash_info(shortstatehash).await?;
 
-		debug!(
+		self.cache_shortstatehash_info(shortstatehash, stack.clone())
-			?shortstatehash,
+			.await?;
-			len = %stack.len(),
-			"cache update"
-		);
-
-		self.stateinfo_cache
-			.lock()
-			.expect("locked")
-			.insert(shortstatehash, stack.clone());
 
 		Ok(stack)
 	}
 
+	/// Returns a stack with info on shortstatehash, full state, added diff and
+	/// removed diff for the selected shortstatehash and each parent layer.
+	#[tracing::instrument(
+		name = "cache",
+		level = "debug",
+		skip_all,
+		fields(
+			?shortstatehash,
+			stack = stack.len(),
+		),
+	)]
+	async fn cache_shortstatehash_info(
+		&self,
+		shortstatehash: ShortStateHash,
+		stack: ShortStateInfoVec,
+	) -> Result {
+		self.stateinfo_cache.lock()?.insert(shortstatehash, stack);
+
+		Ok(())
+	}
+
 	async fn new_shortstatehash_info(
 		&self,
 		shortstatehash: ShortStateHash,

src/service/rooms/timeline/mod.rs

@@ -259,7 +259,7 @@ impl Service {
 	/// happens in `append_pdu`.
 	///
 	/// Returns pdu id
-	#[tracing::instrument(skip_all)]
+	#[tracing::instrument(level = "debug", skip_all)]
 	pub async fn append_pdu(
 		&self,
 		pdu: &PduEvent,
@@ -942,7 +942,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)]
+	#[tracing::instrument(level = "debug", skip_all)]
 	pub async fn append_incoming_pdu(
 		&self,
 		pdu: &PduEvent,