refactor: Clean up logging issues

Primary issues: Double escapes (debug fmt), spans without levels

src/service/admin/grant.rs

@@ -122,7 +122,7 @@ pub async fn make_user_admin(&self, user_id: &UserId) -> Result {
 	let room_tag = self.services.server.config.admin_room_tag.as_str();
 	if !room_tag.is_empty() {
 		if let Err(e) = self.set_room_tag(&room_id, user_id, room_tag).await {
-			error!(?room_id, ?user_id, ?room_tag, "Failed to set tag for admin grant: {e}");
+			error!(%room_id, %user_id, %room_tag, "Failed to set tag for admin grant: {e}");
 		}
 	}
 

src/service/announcements/mod.rs

@@ -96,7 +96,7 @@ impl crate::Service for Service {
 			}
 
 			if let Err(e) = self.check().await {
-				warn!(%e, "Failed to check for announcements");
+				warn!(?e, "Failed to check for announcements");
 			}
 		}
 

src/service/federation/execute.rs

@@ -88,7 +88,7 @@ where
 	let url = request.url().clone();
 	let method = request.method().clone();
 
-	debug!(?method, ?url, "Sending request");
+	debug!(%method, %url, "Sending request");
 	match client.execute(request).await {
 		| Ok(response) => handle_response::<T>(dest, actual, &method, &url, response).await,
 		| Err(error) =>
@@ -144,9 +144,9 @@ async fn into_http_response(
 ) -> Result<http::Response<Bytes>> {
 	let status = response.status();
 	trace!(
-		?status, ?method,
-		request_url = ?url,
-		response_url = ?response.url(),
+		%status, %method,
+		request_url = %url,
+		response_url = %response.url(),
 		"Received response from {}",
 		actual.string(),
 	);
@@ -196,9 +196,9 @@ fn handle_error(
 		debug_warn!("{e:?}");
 	} else if e.is_redirect() {
 		debug_error!(
-			method = ?method,
-			url = ?url,
-			final_url = ?e.url(),
+			%method,
+			%url,
+			final_url = e.url().map(tracing::field::display),
 			"Redirect loop {}: {}",
 			actual.host,
 			e,

src/service/media/data.rs

@@ -124,16 +124,16 @@ impl Data {
 			.next()
 			.map(string_from_bytes)
 			.transpose()
-			.map_err(|e| err!(Database(error!(?mxc, "Content-type is invalid: {e}"))))?;
+			.map_err(|e| err!(Database(error!(%mxc, "Content-type is invalid: {e}"))))?;
 
 		let content_disposition = parts
 			.next()
 			.map(Some)
-			.ok_or_else(|| err!(Database(error!(?mxc, "Media ID in db is invalid."))))?
+			.ok_or_else(|| err!(Database(error!(%mxc, "Media ID in db is invalid."))))?
 			.filter(|bytes| !bytes.is_empty())
 			.map(string_from_bytes)
 			.transpose()
-			.map_err(|e| err!(Database(error!(?mxc, "Content-type is invalid: {e}"))))?
+			.map_err(|e| err!(Database(error!(%mxc, "Content-type is invalid: {e}"))))?
 			.as_deref()
 			.map(str::parse)
 			.transpose()?;

src/service/media/mod.rs

@@ -118,14 +118,14 @@ impl Service {
 		match self.db.search_mxc_metadata_prefix(mxc).await {
 			| Ok(keys) => {
 				for key in keys {
-					trace!(?mxc, "MXC Key: {key:?}");
-					debug_info!(?mxc, "Deleting from filesystem");
+					trace!(%mxc, "MXC Key: {key:?}");
+					debug_info!(%mxc, "Deleting from filesystem");
 
 					if let Err(e) = self.remove_media_file(&key).await {
-						debug_error!(?mxc, "Failed to remove media file: {e}");
+						debug_error!(%mxc, "Failed to remove media file: {e}");
 					}
 
-					debug_info!(?mxc, "Deleting from database");
+					debug_info!(%mxc, "Deleting from database");
 					self.db.delete_file_mxc(mxc).await;
 				}
 
@@ -148,7 +148,7 @@ impl Service {
 
 		for mxc in mxcs {
 			let Ok(mxc) = mxc.as_str().try_into().inspect_err(|e| {
-				debug_error!(?mxc, "Failed to parse MXC URI from database: {e}");
+				debug_error!(%mxc, "Failed to parse MXC URI from database: {e}");
 			}) else {
 				continue;
 			};
@@ -210,7 +210,7 @@ impl Service {
 
 			let Some(mxc_s) = mxc else {
 				debug_warn!(
-					?mxc,
+					mxc,
 					"Parsed MXC URL unicode bytes from database but is still invalid"
 				);
 				continue;
@@ -256,7 +256,7 @@ impl Service {
 
 			let Some(mxc_s) = mxc else {
 				debug_warn!(
-					?mxc,
+					mxc,
 					"Parsed MXC URL unicode bytes from database but is still invalid"
 				);
 				continue;

src/service/media/preview.rs

@@ -71,10 +71,10 @@ async fn request_url_preview(&self, url: &Url) -> Result<UrlPreviewData> {
 	let client = &self.services.client.url_preview;
 	let response = client.head(url.as_str()).send().await?;
 
-	debug!(?url, "URL preview response headers: {:?}", response.headers());
+	debug!(%url, "URL preview response headers: {:?}", response.headers());
 
 	if let Some(remote_addr) = response.remote_addr() {
-		debug!(?url, "URL preview response remote address: {:?}", remote_addr);
+		debug!(%url, "URL preview response remote address: {:?}", remote_addr);
 
 		if let Ok(ip) = IPAddress::parse(remote_addr.ip().to_string()) {
 			if !self.services.client.valid_cidr_range(&ip) {

src/service/media/remote.rs

@@ -247,7 +247,7 @@ async fn handle_location(
 ) -> Result<FileMeta> {
 	self.location_request(location).await.map_err(|error| {
 		err!(Request(NotFound(
-			debug_warn!(%mxc, ?user, ?location, ?error, "Fetching media from location failed")
+			debug_warn!(%mxc, user = user.map(tracing::field::display), ?location, ?error, "Fetching media from location failed")
 		)))
 	})
 }
@@ -320,7 +320,7 @@ fn handle_federation_error(
 ) -> Error {
 	let fallback = || {
 		err!(Request(NotFound(
-			debug_error!(%mxc, ?user, ?server, ?error, "Remote media not found")
+			debug_error!(%mxc, user = user.map(tracing::field::display), server = server.map(tracing::field::display), ?error, "Remote media not found")
 		)))
 	};
 

src/service/media/thumbnail.rs

@@ -120,7 +120,7 @@ async fn get_thumbnail_generate(
 	let mut cursor = std::io::Cursor::new(&mut thumbnail_bytes);
 	thumbnail
 		.write_to(&mut cursor, image::ImageFormat::Png)
-		.map_err(|error| err!(error!(?error, "Error writing PNG thumbnail.")))?;
+		.map_err(|error| err!(error!(%error, "Error writing PNG thumbnail.")))?;
 
 	// Save thumbnail in database so we don't have to generate it again next time
 	let thumbnail_key = self.db.create_file_metadata(

src/service/migrations.rs

@@ -677,7 +677,7 @@ async fn populate_userroomid_leftstate_table(services: &Services) -> Result {
 							shortstatehash_cache.insert(room_id.to_owned(), shortstatehash);
 							shortstatehash
 						} else {
-							warn!(?room_id, ?user_id, "room has no shortstatehash");
+							warn!(%room_id, %user_id, "room has no shortstatehash");
 							return Ok((total, fixed, shortstatehash_cache));
 						};
 
@@ -698,8 +698,8 @@ async fn populate_userroomid_leftstate_table(services: &Services) -> Result {
 						},
 						| Err(_) => {
 							warn!(
-								?room_id,
-								?user_id,
+								%room_id,
+								%user_id,
 								"room cached as left has no leave event for user, removing \
 								 cache entry"
 							);

src/service/presence/mod.rs

@@ -198,11 +198,11 @@ impl Service {
 				presence.presence,
 				PresenceState::Unavailable | PresenceState::Online | PresenceState::Busy
 			) {
-				trace!(?user_id, ?presence, "Skipping user");
+				trace!(%user_id, ?presence, "Skipping user");
 				continue;
 			}
 
-			trace!(?user_id, ?presence, "Resetting presence to offline");
+			trace!(%user_id, ?presence, "Resetting presence to offline");
 
 			_ = self
 				.set_presence(

src/service/rooms/auth_chain/mod.rs

@@ -151,7 +151,7 @@ async fn get_auth_chain_outer(
 			let auth_chain = self.get_auth_chain_inner(room_id, event_id).await?;
 			self.cache_auth_chain_vec(vec![shortid], auth_chain.as_slice());
 			debug!(
-				?event_id,
+				%event_id,
 				elapsed = ?started.elapsed(),
 				"Cache missed event"
 			);
@@ -188,18 +188,18 @@ async fn get_auth_chain_inner(
 	let mut found = HashSet::new();
 
 	while let Some(event_id) = todo.pop_front() {
-		trace!(?event_id, "processing auth event");
+		trace!(%event_id, "processing auth event");
 
 		match self.services.timeline.get_pdu(&event_id).await {
 			| Err(e) => {
-				debug_error!(?event_id, ?e, "Could not find pdu mentioned in auth events");
+				debug_error!(%event_id, ?e, "Could not find pdu mentioned in auth events");
 			},
 			| Ok(pdu) => {
 				if let Some(claimed_room_id) = pdu.room_id.clone() {
 					if claimed_room_id != *room_id {
 						return Err!(Request(Forbidden(error!(
-							?event_id,
-							?room_id,
+							%event_id,
+							%room_id,
 							wrong_room_id = ?pdu.room_id.unwrap(),
 							"auth event for incorrect room"
 						))));
@@ -214,7 +214,7 @@ async fn get_auth_chain_inner(
 						.await;
 
 					if found.insert(sauthevent) {
-						trace!(?event_id, ?auth_event, "adding auth event to processing queue");
+						trace!(%event_id, ?auth_event, "adding auth event to processing queue");
 
 						todo.push_back(auth_event.clone());
 					}

src/service/rooms/event_handler/mod.rs

@@ -104,9 +104,9 @@ fn check_room_id<Pdu: Event>(room_id: &RoomId, pdu: &Pdu) -> Result {
 		.is_some_and(|claimed_room_id| claimed_room_id != room_id)
 	{
 		return Err!(Request(InvalidParam(error!(
-			pdu_event_id = ?pdu.event_id(),
-			pdu_room_id = ?pdu.room_id(),
-			?room_id,
+			pdu_event_id = %pdu.event_id(),
+			pdu_room_id = pdu.room_id().map(tracing::field::display),
+			%room_id,
 			"Found event from room in room",
 		))));
 	}

src/service/rooms/event_handler/policy_server.rs

@@ -31,7 +31,7 @@ use serde_json::value::RawValue;
 /// contacted for whatever reason, Err(e) is returned, which generally is a
 /// fail-open operation.
 #[implement(super::Service)]
-#[tracing::instrument(skip(self, pdu, pdu_json, room_id))]
+#[tracing::instrument(skip(self, pdu, pdu_json, room_id), level = "info")]
 pub async fn ask_policy_server(
 	&self,
 	pdu: &PduEvent,
@@ -184,7 +184,7 @@ pub async fn ask_policy_server(
 /// Asks a remote policy server for a signature on this event.
 /// If the policy server signs this event, the original data is mutated.
 #[implement(super::Service)]
-#[tracing::instrument(skip_all, fields(event_id=%pdu.event_id(), via=%via))]
+#[tracing::instrument(skip_all, fields(event_id=%pdu.event_id(), via=%via), level = "info")]
 pub async fn fetch_policy_server_signature(
 	&self,
 	pdu: &PduEvent,

src/service/rooms/timeline/redact.rs

@@ -28,7 +28,7 @@ pub async fn redact_pdu<Pdu: Event + Send + Sync>(
 		.await
 		.map(Event::into_pdu)
 		.map_err(|e| {
-			err!(Database(error!(?pdu_id, ?event_id, ?e, "PDU ID points to invalid PDU.")))
+			err!(Database(error!(?pdu_id, %event_id, ?e, "PDU ID points to invalid PDU.")))
 		})?;
 
 	if let Ok(content) = pdu.get_content::<ExtractBody>() {
@@ -48,7 +48,7 @@ pub async fn redact_pdu<Pdu: Event + Send + Sync>(
 	pdu.redact(&room_version_id, reason.to_value())?;
 
 	let obj = utils::to_canonical_object(&pdu).map_err(|e| {
-		err!(Database(error!(?event_id, ?e, "Failed to convert PDU to canonical JSON")))
+		err!(Database(error!(%event_id, ?e, "Failed to convert PDU to canonical JSON")))
 	})?;
 
 	self.replace_pdu(&pdu_id, &obj).await

src/service/sending/sender.rs

@@ -535,12 +535,12 @@ impl Service {
 			}
 
 			let Ok(event) = serde_json::from_str(read_receipt.json().get()) else {
-				error!(?user_id, ?count, ?read_receipt, "Invalid edu event in read_receipts.");
+				error!(%user_id, %count, ?read_receipt, "Invalid edu event in read_receipts.");
 				continue;
 			};
 
 			let AnySyncEphemeralRoomEvent::Receipt(r) = event else {
-				error!(?user_id, ?count, ?event, "Invalid event type in read_receipts");
+				error!(%user_id, %count, ?event, "Invalid event type in read_receipts");
 				continue;
 			};
 
@@ -755,7 +755,7 @@ impl Service {
 		let Ok(pusher) = self.services.pusher.get_pusher(&user_id, &pushkey).await else {
 			return Err((
 				Destination::Push(user_id.clone(), pushkey.clone()),
-				err!(Database(error!(?user_id, ?pushkey, "Missing pusher"))),
+				err!(Database(error!(%user_id, ?pushkey, "Missing pusher"))),
 			));
 		};
 

src/service/server_keys/acquire.rs

@@ -118,7 +118,7 @@ where
 	}
 
 	for (server, key_ids) in missing {
-		debug_warn!(?server, ?key_ids, "missing");
+		debug_warn!(%server, ?key_ids, "missing");
 	}
 }
 
@@ -174,8 +174,8 @@ async fn acquire_origin(
 	timeout: Instant,
 ) -> (OwnedServerName, Vec<OwnedServerSigningKeyId>) {
 	match timeout_at(timeout, self.server_request(&origin)).await {
-		| Err(e) => debug_warn!(?origin, "timed out: {e}"),
-		| Ok(Err(e)) => debug_error!(?origin, "{e}"),
+		| Err(e) => debug_warn!(%origin, "timed out: {e}"),
+		| Ok(Err(e)) => debug_error!(%origin, "{e}"),
 		| Ok(Ok(server_keys)) => {
 			trace!(
 				%origin,

src/service/server_keys/get.rs

@@ -63,7 +63,7 @@ where
 }
 
 #[implement(super::Service)]
-#[tracing::instrument(skip(self))]
+#[tracing::instrument(skip(self), level = "debug")]
 pub async fn get_verify_key(
 	&self,
 	origin: &ServerName,
@@ -96,8 +96,8 @@ pub async fn get_verify_key(
 	}
 
 	Err!(BadServerResponse(debug_error!(
-		?key_id,
-		?origin,
+		%key_id,
+		%origin,
 		"Failed to fetch federation signing-key"
 	)))
 }

src/service/server_keys/mod.rs

@@ -112,7 +112,7 @@ async fn add_signing_keys(&self, new_keys: ServerSigningKeys) {
 }
 
 #[implement(Service)]
-#[tracing::instrument(skip(self, object))]
+#[tracing::instrument(skip(self, object), level = "debug")]
 pub async fn required_keys_exist(
 	&self,
 	object: &CanonicalJsonObject,
@@ -135,7 +135,7 @@ pub async fn required_keys_exist(
 }
 
 #[implement(Service)]
-#[tracing::instrument(skip(self))]
+#[tracing::instrument(skip(self), level = "debug")]
 pub async fn verify_key_exists(&self, origin: &ServerName, key_id: &ServerSigningKeyId) -> bool {
 	type KeysMap<'a> = BTreeMap<&'a ServerSigningKeyId, &'a RawJsonValue>;
 

src/service/users/mod.rs

@@ -494,8 +494,8 @@ impl Service {
 		let key = (user_id, device_id);
 		if self.db.userdeviceid_metadata.qry(&key).await.is_err() {
 			return Err!(Database(error!(
-				?user_id,
-				?device_id,
+				%user_id,
+				%device_id,
 				"User does not exist or device has no metadata."
 			)));
 		}
@@ -539,8 +539,8 @@ impl Service {
 		let key = (user_id, device_id);
 		if self.db.userdeviceid_metadata.qry(&key).await.is_err() {
 			return Err!(Database(error!(
-				?user_id,
-				?device_id,
+				%user_id,
+				%device_id,
 				"User does not exist or device has no metadata."
 			)));
 		}
@@ -1153,7 +1153,7 @@ impl Service {
 		let (expires_at, user_id): (u64, OwnedUserId) = value.deserialized()?;
 
 		if expires_at < utils::millis_since_unix_epoch() {
-			trace!(?user_id, ?token, "Removing expired login token");
+			trace!(%user_id, ?token, "Removing expired login token");
 
 			self.db.logintoken_expiresatuserid.remove(token);
 
@@ -1231,7 +1231,7 @@ impl Service {
 		debug!(?uri, "LDAP creating connection...");
 		let (conn, mut ldap) = LdapConnAsync::new(uri.as_str())
 			.await
-			.map_err(|e| err!(Ldap(error!(?user_id, "LDAP connection setup error: {e}"))))?;
+			.map_err(|e| err!(Ldap(error!(%user_id, "LDAP connection setup error: {e}"))))?;
 
 		let driver = self.services.server.runtime().spawn(async move {
 			match conn.drive().await {