backups/grapevine
1
0
Fork 0
mirror of https://gitlab.computer.surgery/matrix/grapevine.git synced 2025-12-17 15:51:23 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions

switch all tracing imports to observability::prelude

Browse source
This commit is contained in:
Olivia Lee 2024-12-14 00:49:56 -08:00
parent bc5f31b3a2
commit 5fca67054e
No known key found for this signature in database
GPG key ID: 54D568A15B9CD1F9
63 changed files with 824 additions and 735 deletions
Download patch file Download diff file Expand all files Collapse all files

13
src/api/appservice_server.rs
View file

@ -5,15 +5,14 @@ use ruma::api::{
appservice::Registration, IncomingResponse, MatrixVersion, OutgoingRequest, appservice::Registration, IncomingResponse, MatrixVersion, OutgoingRequest,
SendAccessToken, SendAccessToken,
}; };
use tracing::warn;
use crate::{services, utils, Error, Result}; use crate::{observability::prelude::*, services, utils, Error, Result};
/// Sends a request to an appservice /// Sends a request to an appservice
/// ///
/// Only returns None if there is no url specified in the appservice /// Only returns None if there is no url specified in the appservice
/// registration file /// registration file
#[tracing::instrument(skip(request))] #[t::instrument(skip(request))]
pub(crate) async fn send_request<T>( pub(crate) async fn send_request<T>(
registration: Registration, registration: Registration,
request: T, request: T,
@ -63,7 +62,7 @@ where
.execute(reqwest_request) .execute(reqwest_request)
.await .await
.inspect_err(|error| { .inspect_err(|error| {
warn!( t::warn!(
%error, %error,
appservice = registration.id, appservice = registration.id,
%destination, %destination,
@ -84,12 +83,12 @@ where
// TODO: handle timeout // TODO: handle timeout
let body = response.bytes().await.unwrap_or_else(|error| { let body = response.bytes().await.unwrap_or_else(|error| {
warn!(%error, "Server error"); t::warn!(%error, "Server error");
Vec::new().into() Vec::new().into()
}); });
if status != 200 { if status != 200 {
warn!( t::warn!(
appservice = %destination, appservice = %destination,
%status, %status,
%url, %url,
@ -108,7 +107,7 @@ where
); );
response.map(Some).map_err(|error| { response.map(Some).map_err(|error| {
warn!( t::warn!(
%error, %error,
appservice = %destination, appservice = %destination,
%url, %url,

14
src/api/client_server/account.rs
View file

@ -16,10 +16,12 @@ use ruma::{
}, },
push, UserId, push, UserId,
}; };
use tracing::{info, warn};
use super::{DEVICE_ID_LENGTH, SESSION_ID_LENGTH, TOKEN_LENGTH}; 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; const RANDOM_USER_ID_LENGTH: usize = 10;
@ -276,7 +278,7 @@ pub(crate) async fn register_route(
body.initial_device_display_name.clone(), 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 { if body.appservice_info.is_none() && !is_guest {
services().admin.send_message(RoomMessageEventContent::notice_plain( services().admin.send_message(RoomMessageEventContent::notice_plain(
format!("New user {user_id} registered on this server."), 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?; services().admin.make_user_admin(&user_id, displayname).await?;
warn!( t::warn!(
%user_id, %user_id,
"Granting admin privileges to the first user", "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( services().admin.send_message(RoomMessageEventContent::notice_plain(
format!("User {sender_user} changed their password."), format!("User {sender_user} changed their password."),
)); ));
@ -455,7 +457,7 @@ pub(crate) async fn deactivate_route(
// Remove devices and mark account as deactivated // Remove devices and mark account as deactivated
services().users.deactivate_account(sender_user)?; 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( services().admin.send_message(RoomMessageEventContent::notice_plain(
format!("User {sender_user} deactivated their account."), format!("User {sender_user} deactivated their account."),
)); ));

7
src/api/client_server/context.rs
View file

@ -7,9 +7,8 @@ use ruma::{
events::StateEventType, events::StateEventType,
uint, 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` /// # `GET /_matrix/client/r0/rooms/{roomId}/context`
/// ///
@ -165,14 +164,14 @@ pub(crate) async fn get_context_route(
if event_type != StateEventType::RoomMember { if event_type != StateEventType::RoomMember {
let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
state.push(pdu.to_state_event()); state.push(pdu.to_state_event());
} else if !lazy_load_enabled || lazy_loaded.contains(&state_key) { } else if !lazy_load_enabled || lazy_loaded.contains(&state_key) {
let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)? let Some(pdu) = services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
state.push(pdu.to_state_event()); state.push(pdu.to_state_event());

17
src/api/client_server/directory.rs
View file

@ -26,10 +26,10 @@ use ruma::{
}, },
uint, ServerName, UInt, uint, ServerName, UInt,
}; };
use tracing::{error, info, warn};
use crate::{ 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` /// # `POST /_matrix/client/r0/publicRooms`
@ -94,7 +94,7 @@ pub(crate) async fn set_room_visibility_route(
match &body.visibility { match &body.visibility {
room::Visibility::Public => { room::Visibility::Public => {
services().rooms.directory.set_public(&body.room_id)?; services().rooms.directory.set_public(&body.room_id)?;
info!( t::info!(
user_id = %sender_user, user_id = %sender_user,
room_id = %body.room_id, room_id = %body.room_id,
"User made room public", "User made room public",
@ -269,7 +269,7 @@ pub(crate) async fn get_public_rooms_filtered_helper(
} }
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument] #[t::instrument]
fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result<PublicRoomsChunk> { fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result<PublicRoomsChunk> {
let canonical_alias = services() let canonical_alias = services()
.rooms .rooms
@ -292,7 +292,7 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result<PublicRoomsChunk> {
.state_cache .state_cache
.room_joined_count(&room_id)? .room_joined_count(&room_id)?
.unwrap_or_else(|| { .unwrap_or_else(|| {
warn!("Room has no member count"); t::warn!("Room has no member count");
0 0
}) })
.try_into() .try_into()
@ -306,7 +306,7 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result<PublicRoomsChunk> {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomTopicEventContent| Some(c.topic)) .map(|c: RoomTopicEventContent| Some(c.topic))
.map_err(|_| { .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.") Error::bad_database("Invalid room topic event in database.")
}) })
})?; })?;
@ -371,7 +371,10 @@ fn room_id_to_chunk(room_id: ruma::OwnedRoomId) -> Result<PublicRoomsChunk> {
_ => None, _ => None,
}) })
.map_err(|error| { .map_err(|error| {
error!(%error, "Invalid room join rule event in database"); t::error!(
%error,
"Invalid room join rule event in database"
);
Error::BadDatabase( Error::BadDatabase(
"Invalid room join rule event in database.", "Invalid room join rule event in database.",
) )

9
src/api/client_server/keys.rs
View file

@ -21,10 +21,11 @@ use ruma::{
ServerName, UserId, ServerName, UserId,
}; };
use serde_json::json; use serde_json::json;
use tracing::debug;
use super::SESSION_ID_LENGTH; 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` /// # `POST /_matrix/client/r0/keys/upload`
/// ///
@ -465,7 +466,7 @@ async fn check_key_requests_back_off(server: &ServerName) -> Result<()> {
if let Some(remaining) = if let Some(remaining) =
min_elapsed_duration.checked_sub(time.elapsed()) 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( return Err(Error::BadServerResponse(
"bad query, still backing off", "bad query, still backing off",
)); ));
@ -504,7 +505,7 @@ async fn request_keys_from(
match &result { match &result {
Ok(_) => reset_key_request_back_off(server).await, Ok(_) => reset_key_request_back_off(server).await,
Err(error) => { 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; back_off_key_requests(server.to_owned()).await;
} }
} }

50
src/api/client_server/media.rs
View file

@ -17,9 +17,9 @@ use ruma::{
}, },
http_headers::{ContentDisposition, ContentDispositionType}, http_headers::{ContentDisposition, ContentDispositionType},
}; };
use tracing::{debug, error, info, warn};
use crate::{ use crate::{
observability::prelude::*,
service::media::FileMeta, service::media::FileMeta,
services, services,
utils::{self, MxcData}, utils::{self, MxcData},
@ -111,7 +111,11 @@ fn set_header_or_panic(
header_value: HeaderValue, header_value: HeaderValue,
) { ) {
if let Some(header_value) = response.headers().get(&header_name) { 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!( panic!(
"expected {header_name:?} to be unset but it was set to \ "expected {header_name:?} to be unset but it was set to \
{header_value:?}" {header_value:?}"
@ -203,12 +207,12 @@ struct RemoteResponse {
/// Fetches remote media content from a URL specified in a /// Fetches remote media content from a URL specified in a
/// `/_matrix/federation/v1/media/*/{mediaId}` `Location` header /// `/_matrix/federation/v1/media/*/{mediaId}` `Location` header
#[tracing::instrument] #[t::instrument]
async fn get_redirected_content( async fn get_redirected_content(
location: String, location: String,
) -> Result<authenticated_media_fed::Content> { ) -> Result<authenticated_media_fed::Content> {
let location = location.parse().map_err(|error| { 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") Error::BadServerResponse("Invalid redirect location")
})?; })?;
let response = services() let response = services()
@ -222,7 +226,7 @@ async fn get_redirected_content(
.get(CONTENT_TYPE) .get(CONTENT_TYPE)
.map(|value| { .map(|value| {
value.to_str().map_err(|error| { value.to_str().map_err(|error| {
error!( t::error!(
?value, ?value,
%error, %error,
"Invalid Content-Type header" "Invalid Content-Type header"
@ -238,7 +242,7 @@ async fn get_redirected_content(
.get(CONTENT_DISPOSITION) .get(CONTENT_DISPOSITION)
.map(|value| { .map(|value| {
ContentDisposition::try_from(value.as_bytes()).map_err(|error| { ContentDisposition::try_from(value.as_bytes()).map_err(|error| {
error!( t::error!(
?value, ?value,
%error, %error,
"Invalid Content-Disposition header" "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( async fn get_remote_content_via_federation_api(
mxc: &MxcData<'_>, mxc: &MxcData<'_>,
) -> Result<RemoteResponse, Error> { ) -> Result<RemoteResponse, Error> {
@ -275,11 +279,11 @@ async fn get_remote_content_via_federation_api(
let content = match content { let content = match content {
authenticated_media_fed::FileOrLocation::File(content) => { authenticated_media_fed::FileOrLocation::File(content) => {
debug!("Got media from remote server"); t::debug!("Got media from remote server");
content content
} }
authenticated_media_fed::FileOrLocation::Location(location) => { authenticated_media_fed::FileOrLocation::Location(location) => {
debug!(location, "Following redirect"); t::debug!(location, "Following redirect");
get_redirected_content(location).await? get_redirected_content(location).await?
} }
}; };
@ -291,7 +295,7 @@ async fn get_remote_content_via_federation_api(
} }
#[allow(deprecated)] // unauthenticated media #[allow(deprecated)] // unauthenticated media
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn get_remote_content_via_legacy_api( async fn get_remote_content_via_legacy_api(
mxc: &MxcData<'_>, mxc: &MxcData<'_>,
) -> Result<RemoteResponse, Error> { ) -> Result<RemoteResponse, Error> {
@ -319,7 +323,7 @@ async fn get_remote_content_via_legacy_api(
}) })
} }
#[tracing::instrument] #[t::instrument]
pub(crate) async fn get_remote_content( pub(crate) async fn get_remote_content(
mxc: &MxcData<'_>, mxc: &MxcData<'_>,
) -> Result<RemoteResponse, Error> { ) -> Result<RemoteResponse, Error> {
@ -327,7 +331,7 @@ pub(crate) async fn get_remote_content(
let response = match fed_result { let response = match fed_result {
Ok(response) => { Ok(response) => {
debug!("Got remote content via authenticated media API"); t::debug!("Got remote content via authenticated media API");
response response
} }
Err(Error::Federation(_, error)) Err(Error::Federation(_, error))
@ -335,7 +339,7 @@ pub(crate) async fn get_remote_content(
// https://github.com/t2bot/matrix-media-repo/issues/609 // https://github.com/t2bot/matrix-media-repo/issues/609
|| error.error_kind() == Some(&ErrorKind::Unauthorized) => || error.error_kind() == Some(&ErrorKind::Unauthorized) =>
{ {
info!( t::info!(
"Remote server does not support authenticated media, falling \ "Remote server does not support authenticated media, falling \
back to deprecated API" 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( async fn get_remote_thumbnail_via_federation_api(
server_name: &ruma::ServerName, server_name: &ruma::ServerName,
request: authenticated_media_fed::get_content_thumbnail::v1::Request, 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 { let content = match content {
authenticated_media_fed::FileOrLocation::File(content) => { authenticated_media_fed::FileOrLocation::File(content) => {
debug!("Got thumbnail from remote server"); t::debug!("Got thumbnail from remote server");
content content
} }
authenticated_media_fed::FileOrLocation::Location(location) => { authenticated_media_fed::FileOrLocation::Location(location) => {
debug!(location, "Following redirect"); t::debug!(location, "Following redirect");
get_redirected_content(location).await? get_redirected_content(location).await?
} }
}; };
@ -744,7 +748,7 @@ async fn get_remote_thumbnail_via_federation_api(
} }
#[allow(deprecated)] // unauthenticated media #[allow(deprecated)] // unauthenticated media
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn get_remote_thumbnail_via_legacy_api( async fn get_remote_thumbnail_via_legacy_api(
server_name: &ruma::ServerName, server_name: &ruma::ServerName,
authenticated_media_fed::get_content_thumbnail::v1::Request { 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( pub(crate) async fn get_remote_thumbnail(
server_name: &ruma::ServerName, server_name: &ruma::ServerName,
request: authenticated_media_fed::get_content_thumbnail::v1::Request, 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 { let response = match fed_result {
Ok(response) => { Ok(response) => {
debug!("Got remote content via authenticated media API"); t::debug!("Got remote content via authenticated media API");
response response
} }
Err(Error::Federation(_, error)) Err(Error::Federation(_, error))
@ -803,7 +807,7 @@ pub(crate) async fn get_remote_thumbnail(
// https://github.com/t2bot/matrix-media-repo/issues/609 // https://github.com/t2bot/matrix-media-repo/issues/609
|| error.error_kind() == Some(&ErrorKind::Unauthorized) => || error.error_kind() == Some(&ErrorKind::Unauthorized) =>
{ {
info!( t::info!(
"Remote server does not support authenticated media, falling \ "Remote server does not support authenticated media, falling \
back to deprecated API" back to deprecated API"
); );
@ -891,7 +895,7 @@ async fn get_content_thumbnail_route_ruma(
resp.content.content_type, resp.content.content_type,
)); ));
} }
Err(error) => warn!( Err(error) => t::warn!(
%error, %error,
"Failed to fetch thumbnail via federation, trying to fetch \ "Failed to fetch thumbnail via federation, trying to fetch \
original media and create thumbnail ourselves" original media and create thumbnail ourselves"
@ -912,7 +916,9 @@ async fn get_content_thumbnail_route_ruma(
return Ok(make_response(file, content_type)); 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.")) Err(Error::BadRequest(ErrorKind::NotYetUploaded, "Media not found."))

66
src/api/client_server/membership.rs
View file

@ -31,10 +31,10 @@ use ruma::{
}; };
use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use serde_json::value::{to_raw_value, RawValue as RawJsonValue};
use tokio::sync::RwLock; use tokio::sync::RwLock;
use tracing::{debug, error, info, warn};
use super::get_alias_helper; use super::get_alias_helper;
use crate::{ use crate::{
observability::prelude::*,
service::{ service::{
globals::SigningKeys, globals::SigningKeys,
pdu::{gen_event_id_canonical_json, PduBuilder}, pdu::{gen_event_id_canonical_json, PduBuilder},
@ -501,7 +501,7 @@ pub(crate) async fn joined_members_route(
} }
#[allow(clippy::too_many_lines)] #[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( async fn join_room_by_id_helper(
sender_user: Option<&UserId>, sender_user: Option<&UserId>,
room_id: &RoomId, room_id: &RoomId,
@ -523,7 +523,7 @@ async fn join_room_by_id_helper(
.state_cache .state_cache
.server_in_room(services().globals.server_name(), room_id)? .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( let join_rules_event = services().rooms.state_accessor.room_state_get(
room_id, room_id,
@ -537,7 +537,7 @@ async fn join_room_by_id_helper(
.map(|join_rules_event| { .map(|join_rules_event| {
serde_json::from_str(join_rules_event.content.get()) serde_json::from_str(join_rules_event.content.get())
.map_err(|error| { .map_err(|error| {
warn!(%error, "Invalid join rules event"); t::warn!(%error, "Invalid join rules event");
Error::bad_database( Error::bad_database(
"Invalid join rules event in db.", "Invalid join rules event in db.",
) )
@ -636,7 +636,7 @@ async fn join_room_by_id_helper(
return Err(error); return Err(error);
} }
info!( t::info!(
"We couldn't do the join locally, maybe federation can help to \ "We couldn't do the join locally, maybe federation can help to \
satisfy the restricted join requirements" satisfy the restricted join requirements"
); );
@ -791,12 +791,12 @@ async fn join_room_by_id_helper(
) )
.await?; .await?;
} else { } else {
info!("Joining over federation."); t::info!("Joining over federation.");
let (make_join_response, remote_server) = let (make_join_response, remote_server) =
make_join_request(sender_user, room_id, servers).await?; 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 { let room_version_id = match make_join_response.room_version {
Some(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 // It has enough fields to be called a proper event now
let mut join_event = join_event_stub; 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() let send_join_response = services()
.sending .sending
.send_federation_request( .send_federation_request(
@ -911,10 +911,10 @@ async fn join_room_by_id_helper(
) )
.await?; .await?;
info!("send_join finished"); t::info!("send_join finished");
if let Some(signed_raw) = &send_join_response.room_state.event { if let Some(signed_raw) = &send_join_response.room_state.event {
info!( t::info!(
"There is a signed event. This room is probably using \ "There is a signed event. This room is probably using \
restricted joins. Adding signature to our event" 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()); .insert(remote_server.to_string(), signature.clone());
} }
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
server = %remote_server, server = %remote_server,
event = ?signed_value, event = ?signed_value,
@ -969,7 +969,7 @@ async fn join_room_by_id_helper(
services().rooms.short.get_or_create_shortroomid(room_id)?; services().rooms.short.get_or_create_shortroomid(room_id)?;
info!("Parsing join event"); t::info!("Parsing join event");
let parsed_join_pdu = let parsed_join_pdu =
PduEvent::from_id_val(event_id, join_event.clone()).map_err( PduEvent::from_id_val(event_id, join_event.clone()).map_err(
|_| Error::BadServerResponse("Invalid join event PDU."), |_| Error::BadServerResponse("Invalid join event PDU."),
@ -978,7 +978,7 @@ async fn join_room_by_id_helper(
let mut state = HashMap::new(); let mut state = HashMap::new();
let pub_key_map = RwLock::new(BTreeMap::new()); let pub_key_map = RwLock::new(BTreeMap::new());
info!("Fetching join signing keys"); t::info!("Fetching join signing keys");
services() services()
.rooms .rooms
.event_handler .event_handler
@ -989,7 +989,7 @@ async fn join_room_by_id_helper(
) )
.await?; .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| { for result in send_join_response.room_state.state.iter().map(|pdu| {
validate_and_add_event_id(pdu, &room_version_id, &pub_key_map) 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( let pdu = PduEvent::from_id_val(&event_id, value.clone()).map_err(
|error| { |error| {
warn!( t::warn!(
%error, %error,
object = ?value, object = ?value,
"Invalid PDU in send_join response", "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 for result in
send_join_response.room_state.auth_chain.iter().map(|pdu| { send_join_response.room_state.auth_chain.iter().map(|pdu| {
validate_and_add_event_id(pdu, &room_version_id, &pub_key_map) 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)?; 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( let authenticated = state_res::event_auth::auth_check(
&state_res::RoomVersion::new(&room_version_id).map_err(|_| { &state_res::RoomVersion::new(&room_version_id).map_err(|_| {
Error::UnsupportedRoomVersion(room_version_id.clone()) Error::UnsupportedRoomVersion(room_version_id.clone())
@ -1062,7 +1062,7 @@ async fn join_room_by_id_helper(
}, },
) )
.map_err(|error| { .map_err(|error| {
warn!(%error, "Auth check failed"); t::warn!(%error, "Auth check failed");
Error::BadRequest(ErrorKind::InvalidParam, "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) = let (statehash_before_join, new, removed) =
services().rooms.state_compressor.save_state( services().rooms.state_compressor.save_state(
room_id, room_id,
@ -1096,7 +1096,7 @@ async fn join_room_by_id_helper(
.force_state(&room_token, statehash_before_join, new, removed) .force_state(&room_token, statehash_before_join, new, removed)
.await?; .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)?; services().rooms.state_cache.update_joined_count(room_id)?;
// We append to state before appending the pdu, so we don't have a // 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 = let statehash_after_join =
services().rooms.state.append_to_state(&parsed_join_pdu)?; services().rooms.state.append_to_state(&parsed_join_pdu)?;
info!("Appending new room join event"); t::info!("Appending new room join event");
services() services()
.rooms .rooms
.timeline .timeline
@ -1117,7 +1117,7 @@ async fn join_room_by_id_helper(
) )
.await?; .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 // 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 // a moment in time where events in the current room state do
// not exist // not exist
@ -1146,7 +1146,7 @@ async fn make_join_request(
if remote_server == services().globals.server_name() { if remote_server == services().globals.server_name() {
continue; 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() let make_join_response = services()
.sending .sending
.send_federation_request( .send_federation_request(
@ -1164,7 +1164,7 @@ async fn make_join_request(
return Ok((r, remote_server.clone())); return Ok((r, remote_server.clone()));
} }
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
server = %remote_server, server = %remote_server,
"Remote join request failed", "Remote join request failed",
@ -1184,7 +1184,7 @@ async fn validate_and_add_event_id(
) -> Result<(OwnedEventId, CanonicalJsonObject)> { ) -> Result<(OwnedEventId, CanonicalJsonObject)> {
let mut value: CanonicalJsonObject = serde_json::from_str(pdu.get()) let mut value: CanonicalJsonObject = serde_json::from_str(pdu.get())
.map_err(|error| { .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") Error::BadServerResponse("Invalid PDU in server response")
})?; })?;
let event_id = EventId::parse(format!( let event_id = EventId::parse(format!(
@ -1216,7 +1216,7 @@ async fn validate_and_add_event_id(
} }
if time.elapsed() < min_elapsed_duration { 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( return Err(Error::BadServerResponse(
"bad event, still backing off", "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(|| { 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( Error::BadRequest(
ErrorKind::MissingParam, ErrorKind::MissingParam,
"Invalid PDU, no origin_server_ts field", "Invalid PDU, no origin_server_ts field",
@ -1258,7 +1258,7 @@ async fn validate_and_add_event_id(
if let Err(error) = if let Err(error) =
ruma::signatures::verify_event(&keys, &value, room_version) ruma::signatures::verify_event(&keys, &value, room_version)
{ {
warn!( t::warn!(
%event_id, %event_id,
%error, %error,
?pdu, ?pdu,
@ -1361,7 +1361,7 @@ pub(crate) async fn invite_helper(
}; };
if *pdu.event_id != *event_id { if *pdu.event_id != *event_id {
warn!( t::warn!(
server = %user_id.server_name(), server = %user_id.server_name(),
our_object = ?pdu_json, our_object = ?pdu_json,
their_object = ?value, 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 { 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(()) Ok(())
} }
#[tracing::instrument(skip(reason))] #[t::instrument(skip(reason))]
pub(crate) async fn leave_room( pub(crate) async fn leave_room(
user_id: &UserId, user_id: &UserId,
room_id: &RoomId, room_id: &RoomId,
@ -1515,7 +1515,7 @@ pub(crate) async fn leave_room(
// Fix for broken rooms // Fix for broken rooms
let member_event = match member_event { let member_event = match member_event {
None => { 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( services().rooms.state_cache.update_membership(
room_id, room_id,
@ -1557,7 +1557,7 @@ pub(crate) async fn leave_room(
.await?; .await?;
} else { } else {
if let Err(error) = remote_leave_room(user_id, room_id).await { 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 // Don't tell the client about this error
} }

10
src/api/client_server/profile.rs
View file

@ -14,9 +14,11 @@ use ruma::{
}, },
}; };
use serde_json::value::to_raw_value; 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` /// # `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) .build_and_append_pdu(pdu_builder, sender_user, &room_token)
.await .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) .build_and_append_pdu(pdu_builder, sender_user, &room_token)
.await .await
{ {
warn!(%error, "failed to add PDU"); t::warn!(%error, "failed to add PDU");
}; };
} }

14
src/api/client_server/room.rs
View file

@ -27,11 +27,11 @@ use ruma::{
CanonicalJsonObject, OwnedRoomAliasId, RoomAliasId, RoomId, CanonicalJsonObject, OwnedRoomAliasId, RoomAliasId, RoomId,
}; };
use serde_json::{json, value::to_raw_value}; use serde_json::{json, value::to_raw_value};
use tracing::{info, warn};
use crate::{ use crate::{
api::client_server::invite_helper, service::pdu::PduBuilder, services, api::client_server::invite_helper, observability::prelude::*,
utils::room_version::RoomVersion, Ar, Error, Ra, Result, service::pdu::PduBuilder, services, utils::room_version::RoomVersion, Ar,
Error, Ra, Result,
}; };
/// # `POST /_matrix/client/r0/createRoom` /// # `POST /_matrix/client/r0/createRoom`
@ -400,7 +400,7 @@ pub(crate) async fn create_room_route(
for event in &body.initial_state { for event in &body.initial_state {
let mut pdu_builder = let mut pdu_builder =
event.deserialize_as::<PduBuilder>().map_err(|error| { event.deserialize_as::<PduBuilder>().map_err(|error| {
warn!(%error, "Invalid initial state event"); t::warn!(%error, "Invalid initial state event");
Error::BadRequest( Error::BadRequest(
ErrorKind::InvalidParam, ErrorKind::InvalidParam,
"Invalid initial state event.", "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) invite_helper(sender_user, user_id, &room_id, None, body.is_direct)
.await .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)?; 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))) 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( 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.") Error::BadRequest(ErrorKind::NotFound, "Event not found.")
}, },
)?; )?;

22
src/api/client_server/session.rs
View file

@ -13,10 +13,11 @@ use ruma::{
UserId, UserId,
}; };
use serde::Deserialize; use serde::Deserialize;
use tracing::{info, warn};
use super::{DEVICE_ID_LENGTH, TOKEN_LENGTH}; 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)] #[derive(Debug, Deserialize)]
struct Claims { struct Claims {
@ -79,7 +80,7 @@ pub(crate) async fn login_route(
} else if let Some(user) = user { } else if let Some(user) = user {
UserId::parse(user) UserId::parse(user)
} else { } else {
warn!(kind = ?body.login_info, "Bad login kind"); t::warn!(kind = ?body.login_info, "Bad login kind");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Bad login type.", "Bad login type.",
@ -184,7 +185,7 @@ pub(crate) async fn login_route(
} else if let Some(user) = user { } else if let Some(user) = user {
UserId::parse(user) UserId::parse(user)
} else { } else {
warn!(kind = ?body.login_info, "Bad login kind"); t::warn!(kind = ?body.login_info, "Bad login kind");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Bad login type.", "Bad login type.",
@ -214,7 +215,10 @@ pub(crate) async fn login_route(
user_id 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( return Err(Error::BadRequest(
ErrorKind::Unknown, ErrorKind::Unknown,
"Unsupported login type.", "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 // Homeservers are still required to send the `home_server` field
#[allow(deprecated)] #[allow(deprecated)]
@ -292,7 +296,11 @@ pub(crate) async fn logout_route(
services().users.remove_device(sender_user, sender_device)?; 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())) Ok(Ra(logout::v3::Response::new()))
} }

18
src/api/client_server/state.rs
View file

@ -13,9 +13,11 @@ use ruma::{
EventId, RoomAliasId, RoomId, UserId, EventId, RoomAliasId, RoomId, UserId,
}; };
use serde::Deserialize; 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}` /// # `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 .state_accessor
.room_state_get(&body.room_id, &body.event_type, &body.state_key)? .room_state_get(&body.room_id, &body.event_type, &body.state_key)?
.ok_or_else(|| { .ok_or_else(|| {
warn!( t::warn!(
"State event {:?} not found in room {:?}", "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.") 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 .state_accessor
.room_state_get(&body.room_id, &body.event_type, "")? .room_state_get(&body.room_id, &body.event_type, "")?
.ok_or_else(|| { .ok_or_else(|| {
warn!( t::warn!(
"State event {:?} not found in room {:?}", "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.") Error::BadRequest(ErrorKind::NotFound, "State event not found.")
})?; })?;
@ -278,7 +282,7 @@ async fn validate_canonical_alias_event(
.and_then(|old_event| { .and_then(|old_event| {
serde_json::from_str::<Extract>(old_event.content.get()) serde_json::from_str::<Extract>(old_event.content.get())
.inspect_err(|error| { .inspect_err(|error| {
warn!( t::warn!(
%error, %error,
event_id=%old_event.event_id, event_id=%old_event.event_id,
"Invalid canonical alias event in database" "Invalid canonical alias event in database"

6
src/api/client_server/sync.rs
View file

@ -1,8 +1,8 @@
use ruma::{events::StateEventType, RoomId, UserId}; use ruma::{events::StateEventType, RoomId, UserId};
use tracing::error;
use crate::{ use crate::{
service::rooms::timeline::PduCount, services, Error, PduEvent, Result, observability::prelude::*, service::rooms::timeline::PduCount, services,
Error, PduEvent, Result,
}; };
pub(crate) mod msc3575; pub(crate) mod msc3575;
@ -26,7 +26,7 @@ fn load_timeline(
.filter_map(|x| match x { .filter_map(|x| match x {
Ok(x) => Some(x), Ok(x) => Some(x),
Err(error) => { Err(error) => {
error!(%error, "Bad PDU in pdus_since"); t::error!(%error, "Bad PDU in pdus_since");
None None
} }
}) })

15
src/api/client_server/sync/msc3575.rs
View file

@ -21,11 +21,11 @@ use ruma::{
}, },
uint, JsOption, UInt, UserId, uint, JsOption, UInt, UserId,
}; };
use tracing::{debug, error};
use super::{load_timeline, share_encrypted_room}; use super::{load_timeline, share_encrypted_room};
use crate::{ 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)] #[allow(clippy::too_many_lines)]
@ -93,7 +93,7 @@ pub(crate) async fn sync_events_v4_route(
let Some(current_shortstatehash) = let Some(current_shortstatehash) =
services().rooms.state.get_room_shortstatehash(room_id)? services().rooms.state.get_room_shortstatehash(room_id)?
else { else {
error!(%room_id, "Room has no state"); t::error!(%room_id, "Room has no state");
continue; continue;
}; };
@ -171,7 +171,10 @@ pub(crate) async fn sync_events_v4_route(
let Some(pdu) = let Some(pdu) =
services().rooms.timeline.get_pdu(&event_id)? services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(
%event_id,
"Event in state not found"
);
continue; continue;
}; };
if pdu.kind == TimelineEventType::RoomMember { if pdu.kind == TimelineEventType::RoomMember {
@ -450,7 +453,7 @@ pub(crate) async fn sync_events_v4_route(
.map_or(Ok::<_, Error>(None), |(pdu_count, _)| { .map_or(Ok::<_, Error>(None), |(pdu_count, _)| {
Ok(Some(match pdu_count { Ok(Some(match pdu_count {
PduCount::Backfilled(_) => { PduCount::Backfilled(_) => {
error!("Timeline in backfill state?!"); t::error!("Timeline in backfill state?!");
"0".to_owned() "0".to_owned()
} }
PduCount::Normal(c) => c.to_string(), 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 { match tokio::time::timeout(duration, watcher).await {
Ok(x) => x.expect("watcher should succeed"), Ok(x) => x.expect("watcher should succeed"),
Err(error) => debug!(%error, "Timed out"), Err(error) => t::debug!(%error, "Timed out"),
}; };
} }

38
src/api/client_server/sync/v3.rs
View file

@ -23,10 +23,10 @@ use ruma::{
}, },
uint, DeviceId, EventId, OwnedRoomId, OwnedUserId, RoomId, UInt, UserId, uint, DeviceId, EventId, OwnedRoomId, OwnedUserId, RoomId, UInt, UserId,
}; };
use tracing::{debug, error, field};
use super::{load_timeline, share_encrypted_room}; use super::{load_timeline, share_encrypted_room};
use crate::{ use crate::{
observability::prelude::*,
service::{pdu::EventHash, rooms::timeline::PduCount}, service::{pdu::EventHash, rooms::timeline::PduCount},
services, utils, Ar, Error, PduEvent, Ra, Result, 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: /// - If the user left after `since`: `prev_batch` token, empty state (TODO:
/// subset of the state at the point of the leave) /// subset of the state at the point of the leave)
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument( #[t::instrument(
skip_all, skip_all,
fields( fields(
sender_user, sender_user,
@ -99,12 +99,12 @@ struct SyncContext<'a> {
pub(crate) async fn sync_events_route( pub(crate) async fn sync_events_route(
body: Ar<sync_events::v3::Request>, body: Ar<sync_events::v3::Request>,
) -> Result<Ra<sync_events::v3::Response>, Ra<UiaaResponse>> { ) -> Result<Ra<sync_events::v3::Response>, Ra<UiaaResponse>> {
let current_span = tracing::Span::current(); let current_span = t::Span::current();
let sender_user = body.sender_user.expect("user is authenticated"); 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"); 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; let body = body.body;
// Setup watchers, so if there's no response, we can wait for them // 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 { match tokio::time::timeout(duration, watcher).await {
Ok(x) => x.expect("watcher should succeed"), Ok(x) => x.expect("watcher should succeed"),
Err(error) => debug!(%error, "Timed out"), Err(error) => t::debug!(%error, "Timed out"),
}; };
} }
Ok(Ra(response)) Ok(Ra(response))
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn collect_joined_rooms( async fn collect_joined_rooms(
ctx: &SyncContext<'_>, ctx: &SyncContext<'_>,
device_list_updates: &mut HashSet<OwnedUserId>, device_list_updates: &mut HashSet<OwnedUserId>,
@ -316,7 +316,7 @@ async fn collect_joined_rooms(
Ok(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)] #[allow(clippy::too_many_arguments, clippy::too_many_lines)]
async fn load_joined_room( async fn load_joined_room(
ctx: &SyncContext<'_>, ctx: &SyncContext<'_>,
@ -366,7 +366,7 @@ async fn load_joined_room(
let Some(current_shortstatehash) = let Some(current_shortstatehash) =
services().rooms.state.get_room_shortstatehash(room_id)? services().rooms.state.get_room_shortstatehash(room_id)?
else { else {
error!("Room has no state"); t::error!("Room has no state");
return Err(Error::BadDatabase("Room has no state")); return Err(Error::BadDatabase("Room has no state"));
}; };
@ -526,7 +526,7 @@ async fn load_joined_room(
let Some(pdu) = let Some(pdu) =
services().rooms.timeline.get_pdu(&event_id)? services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
state_events.push(pdu); state_events.push(pdu);
@ -544,7 +544,7 @@ async fn load_joined_room(
let Some(pdu) = let Some(pdu) =
services().rooms.timeline.get_pdu(&event_id)? services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
@ -615,7 +615,7 @@ async fn load_joined_room(
let Some(pdu) = let Some(pdu) =
services().rooms.timeline.get_pdu(&event_id)? services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
@ -748,7 +748,7 @@ async fn load_joined_room(
lazy_loaded.insert(state_key_userid); lazy_loaded.insert(state_key_userid);
} }
Err(error) => { Err(error) => {
error!( t::error!(
event_id = %pdu.event_id, event_id = %pdu.event_id,
%error, %error,
"Invalid state key for member event", "Invalid state key for member event",
@ -834,7 +834,7 @@ async fn load_joined_room(
|(pdu_count, _)| { |(pdu_count, _)| {
Ok(Some(match pdu_count { Ok(Some(match pdu_count {
PduCount::Backfilled(_) => { PduCount::Backfilled(_) => {
error!("Timeline in backfill state?!"); t::error!("Timeline in backfill state?!");
"0".to_owned() "0".to_owned()
} }
PduCount::Normal(c) => c.to_string(), 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( async fn collect_left_rooms(
ctx: &SyncContext<'_>, ctx: &SyncContext<'_>,
) -> Result<BTreeMap<OwnedRoomId, LeftRoom>> { ) -> Result<BTreeMap<OwnedRoomId, LeftRoom>> {
@ -1017,7 +1017,7 @@ async fn collect_left_rooms(
ctx.sender_user.as_str(), ctx.sender_user.as_str(),
)? )?
else { else {
error!("Left room but no left state event"); t::error!("Left room but no left state event");
continue; continue;
}; };
@ -1026,7 +1026,7 @@ async fn collect_left_rooms(
.state_accessor .state_accessor
.pdu_shortstatehash(&left_event_id)? .pdu_shortstatehash(&left_event_id)?
else { else {
error!("Leave event has no state"); t::error!("Leave event has no state");
continue; continue;
}; };
@ -1059,7 +1059,7 @@ async fn collect_left_rooms(
let Some(pdu) = let Some(pdu) =
services().rooms.timeline.get_pdu(&event_id)? services().rooms.timeline.get_pdu(&event_id)?
else { else {
error!(%event_id, "Event in state not found"); t::error!(%event_id, "Event in state not found");
continue; continue;
}; };
@ -1094,7 +1094,7 @@ async fn collect_left_rooms(
Ok(left_rooms) Ok(left_rooms)
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn collect_invited_rooms( async fn collect_invited_rooms(
ctx: &SyncContext<'_>, ctx: &SyncContext<'_>,
) -> Result<BTreeMap<OwnedRoomId, InvitedRoom>> { ) -> Result<BTreeMap<OwnedRoomId, InvitedRoom>> {

25
src/api/ruma_wrapper/axum.rs
View file

@ -25,10 +25,12 @@ use ruma::{
OwnedServerName, OwnedUserId, UserId, OwnedServerName, OwnedUserId, UserId,
}; };
use serde::Deserialize; use serde::Deserialize;
use tracing::{error, warn};
use super::{Ar, Ra}; use super::{Ar, Ra};
use crate::{service::appservice::RegistrationInfo, services, Error, Result}; use crate::{
observability::prelude::*, service::appservice::RegistrationInfo, services,
Error, Result,
};
enum Token { enum Token {
Appservice(Box<RegistrationInfo>), Appservice(Box<RegistrationInfo>),
@ -82,7 +84,7 @@ async fn ar_from_request_inner(
let query_params: QueryParams = match serde_html_form::from_str(query) { let query_params: QueryParams = match serde_html_form::from_str(query) {
Ok(params) => params, Ok(params) => params,
Err(error) => { Err(error) => {
error!(%error, %query, "Failed to deserialize query parameters"); t::error!(%error, %query, "Failed to deserialize query parameters");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::Unknown, ErrorKind::Unknown,
"Failed to read query parameters", "Failed to read query parameters",
@ -182,7 +184,10 @@ async fn ar_from_request_inner(
.extract::<TypedHeader<Authorization<XMatrix>>>() .extract::<TypedHeader<Authorization<XMatrix>>>()
.await .await
.map_err(|error| { .map_err(|error| {
warn!(%error, "Missing or invalid Authorization header"); t::warn!(
%error,
"Missing or invalid Authorization header"
);
let msg = match error.reason() { let msg = match error.reason() {
TypedHeaderRejectionReason::Missing => { TypedHeaderRejectionReason::Missing => {
@ -199,7 +204,7 @@ async fn ar_from_request_inner(
if let Some(destination) = x_matrix.destination { if let Some(destination) = x_matrix.destination {
if destination != services().globals.server_name() { if destination != services().globals.server_name() {
warn!( t::warn!(
%destination, %destination,
"Incorrect destination in X-Matrix header" "Incorrect destination in X-Matrix header"
); );
@ -278,7 +283,7 @@ async fn ar_from_request_inner(
let keys = match keys_result { let keys = match keys_result {
Ok(b) => b, Ok(b) => b,
Err(error) => { Err(error) => {
warn!(%error, "Failed to fetch signing keys"); t::warn!(%error, "Failed to fetch signing keys");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Failed to fetch signing keys.", "Failed to fetch signing keys.",
@ -304,7 +309,7 @@ async fn ar_from_request_inner(
{ {
Ok(()) => (None, None, Some(x_matrix.origin), None), Ok(()) => (None, None, Some(x_matrix.origin), None),
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
origin = %x_matrix.origin, origin = %x_matrix.origin,
object = ?request_map, object = ?request_map,
@ -312,7 +317,7 @@ async fn ar_from_request_inner(
); );
if parts.uri.to_string().contains('@') { if parts.uri.to_string().contains('@') {
warn!( t::warn!(
"Request uri contained '@' character. Make \ "Request uri contained '@' character. Make \
sure your reverse proxy gives Grapevine the \ sure your reverse proxy gives Grapevine the \
raw uri (apache: use nocanon)" raw uri (apache: use nocanon)"
@ -405,7 +410,7 @@ where
{ {
type Rejection = Error; type Rejection = Error;
#[tracing::instrument("ar_from_request", skip_all)] #[t::instrument("ar_from_request", skip_all)]
async fn from_request( async fn from_request(
req: axum::extract::Request, req: axum::extract::Request,
_state: &S, _state: &S,
@ -415,7 +420,7 @@ where
let body = let body =
T::try_from_http_request(pieces.http_request, &pieces.path_params) T::try_from_http_request(pieces.http_request, &pieces.path_params)
.map_err(|error| { .map_err(|error| {
warn!( t::warn!(
%error, %error,
body = ?pieces.json_body, body = ?pieces.json_body,
"Request body JSON structure is incorrect" "Request body JSON structure is incorrect"

127
src/api/server_server.rs
View file

@ -63,12 +63,11 @@ use ruma::{
}; };
use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use serde_json::value::{to_raw_value, RawValue as RawJsonValue};
use tokio::sync::RwLock; use tokio::sync::RwLock;
use tracing::{debug, error, field, trace, trace_span, warn};
use super::appservice_server; use super::appservice_server;
use crate::{ use crate::{
api::client_server::{self, claim_keys_helper, get_keys_helper}, api::client_server::{self, claim_keys_helper, get_keys_helper},
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
service::{ service::{
globals::SigningKeys, globals::SigningKeys,
pdu::{gen_event_id_canonical_json, PduBuilder}, pdu::{gen_event_id_canonical_json, PduBuilder},
@ -147,7 +146,7 @@ pub(crate) enum AllowLoopbackRequests {
No, 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<T>( pub(crate) async fn send_request<T>(
destination: &ServerName, destination: &ServerName,
request: T, 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; let mut write_destination_to_cache = false;
@ -201,7 +200,7 @@ where
&[MatrixVersion::V1_11], &[MatrixVersion::V1_11],
) )
.map_err(|error| { .map_err(|error| {
warn!( t::warn!(
%error, %error,
actual_destination = actual_destination_str, actual_destination = actual_destination_str,
"Failed to find destination", "Failed to find destination",
@ -273,8 +272,8 @@ where
// can be enabled selectively using `filter = // can be enabled selectively using `filter =
// grapevine[outgoing_request_curl]=trace` in config // grapevine[outgoing_request_curl]=trace` in config
trace_span!("outgoing_request_curl").in_scope(|| { t::trace_span!("outgoing_request_curl").in_scope(|| {
trace!( t::trace!(
cmd = utils::curlify(&http_request), cmd = utils::curlify(&http_request),
"curl command line for outgoing request" "curl command line for outgoing request"
); );
@ -282,21 +281,21 @@ where
let reqwest_request = reqwest::Request::try_from(http_request)?; let reqwest_request = reqwest::Request::try_from(http_request)?;
let url = reqwest_request.url().clone(); 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 = let response =
services().globals.federation_client().execute(reqwest_request).await; services().globals.federation_client().execute(reqwest_request).await;
let mut response = response.inspect_err(|error| { let mut response = response.inspect_err(|error| {
if log_error == LogRequestError::Yes { if log_error == LogRequestError::Yes {
warn!(%error, "Could not send request"); t::warn!(%error, "Could not send request");
} }
})?; })?;
// reqwest::Response -> http::Response conversion // reqwest::Response -> http::Response conversion
let status = response.status(); let status = response.status();
debug!(status = u16::from(status), "Received response"); t::debug!(status = u16::from(status), "Received response");
let mut http_response_builder = let mut http_response_builder =
http::Response::builder().status(status).version(response.version()); http::Response::builder().status(status).version(response.version());
mem::swap( mem::swap(
@ -306,16 +305,16 @@ where
.expect("http::response::Builder is usable"), .expect("http::response::Builder is usable"),
); );
debug!("Getting response bytes"); t::debug!("Getting response bytes");
// TODO: handle timeout // TODO: handle timeout
let body = response.bytes().await.unwrap_or_else(|error| { let body = response.bytes().await.unwrap_or_else(|error| {
warn!(%error, "Server error"); t::warn!(%error, "Server error");
Vec::new().into() Vec::new().into()
}); });
debug!("Got response bytes"); t::debug!("Got response bytes");
if status != 200 { if status != 200 {
warn!( t::warn!(
status = u16::from(status), status = u16::from(status),
response = response =
dbg_truncate_str(String::from_utf8_lossy(&body).as_ref(), 100) 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); let response = T::IncomingResponse::try_from_http_response(http_response);
if response.is_ok() && write_destination_to_cache { if response.is_ok() && write_destination_to_cache {
METRICS.record_lookup(Lookup::FederationDestination, FoundIn::Remote); METRICS.record_lookup(Lookup::FederationDestination, FoundIn::Remote);
@ -346,7 +345,7 @@ where
} }
response.map_err(|e| { response.map_err(|e| {
warn!(error = %e, "Invalid 200 response"); t::warn!(error = %e, "Invalid 200 response");
Error::BadServerResponse("Server returned bad 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 /// Numbers in comments below refer to bullet points in linked section of
/// specification /// specification
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument(ret(level = "debug"))] #[t::instrument(ret(level = "debug"))]
async fn find_actual_destination( async fn find_actual_destination(
destination: &'_ ServerName, destination: &'_ ServerName,
) -> (FedDest, FedDest) { ) -> (FedDest, FedDest) {
debug!("Finding actual destination"); t::debug!("Finding actual destination");
let destination_str = destination.as_str().to_owned(); let destination_str = destination.as_str().to_owned();
let mut hostname = destination_str.clone(); let mut hostname = destination_str.clone();
let actual_destination = match get_ip_with_port(&destination_str) { let actual_destination = match get_ip_with_port(&destination_str) {
Some(host_port) => { Some(host_port) => {
debug!("1: IP literal with provided or default port"); t::debug!("1: IP literal with provided or default port");
host_port host_port
} }
None => { None => {
if let Some(pos) = destination_str.find(':') { 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); let (host, port) = destination_str.split_at(pos);
FedDest::Named(host.to_owned(), port.to_owned()) FedDest::Named(host.to_owned(), port.to_owned())
} else { } else {
debug!(%destination, "Requesting well known"); t::debug!(%destination, "Requesting well known");
if let Some(delegated_hostname) = if let Some(delegated_hostname) =
request_well_known(destination.as_str()).await 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) hostname = add_port_to_hostname(&delegated_hostname)
.to_uri_string(); .to_uri_string();
if let Some(host_and_port) = if let Some(host_and_port) =
@ -404,15 +403,19 @@ async fn find_actual_destination(
{ {
host_and_port host_and_port
} else if let Some(pos) = delegated_hostname.find(':') { } 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); let (host, port) = delegated_hostname.split_at(pos);
FedDest::Named(host.to_owned(), port.to_owned()) FedDest::Named(host.to_owned(), port.to_owned())
} else { } 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) = if let Some(hostname_override) =
query_srv_record(&delegated_hostname).await 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(); let force_port = hostname_override.port();
if let Ok(override_ip) = services() if let Ok(override_ip) = services()
@ -434,7 +437,7 @@ async fn find_actual_destination(
), ),
); );
} else { } else {
warn!( t::warn!(
"Using SRV record, but could not resolve \ "Using SRV record, but could not resolve \
to IP" to IP"
); );
@ -449,7 +452,7 @@ async fn find_actual_destination(
add_port_to_hostname(&delegated_hostname) add_port_to_hostname(&delegated_hostname)
} }
} else { } else {
debug!( t::debug!(
"3.4: No SRV records, just use the hostname \ "3.4: No SRV records, just use the hostname \
from .well-known" from .well-known"
); );
@ -457,11 +460,11 @@ async fn find_actual_destination(
} }
} }
} else { } 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) = if let Some(hostname_override) =
query_srv_record(&destination_str).await query_srv_record(&destination_str).await
{ {
debug!("4: SRV record found"); t::debug!("4: SRV record found");
let force_port = hostname_override.port(); let force_port = hostname_override.port();
if let Ok(override_ip) = services() if let Ok(override_ip) = services()
@ -483,7 +486,7 @@ async fn find_actual_destination(
), ),
); );
} else { } else {
warn!( t::warn!(
"Using SRV record, but could not resolve to IP" "Using SRV record, but could not resolve to IP"
); );
} }
@ -494,14 +497,14 @@ async fn find_actual_destination(
add_port_to_hostname(&hostname) add_port_to_hostname(&hostname)
} }
} else { } else {
debug!("5: No SRV record found"); t::debug!("5: No SRV record found");
add_port_to_hostname(&destination_str) 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 // 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 // to an IP address if it wasn't specified
@ -518,7 +521,7 @@ async fn find_actual_destination(
(actual_destination, hostname) (actual_destination, hostname)
} }
#[tracing::instrument(ret(level = "debug"))] #[t::instrument(ret(level = "debug"))]
async fn query_given_srv_record(record: &str) -> Option<FedDest> { async fn query_given_srv_record(record: &str) -> Option<FedDest> {
services() services()
.globals .globals
@ -540,7 +543,7 @@ async fn query_given_srv_record(record: &str) -> Option<FedDest> {
.unwrap_or(None) .unwrap_or(None)
} }
#[tracing::instrument(ret(level = "debug"))] #[t::instrument(ret(level = "debug"))]
async fn query_srv_record(hostname: &'_ str) -> Option<FedDest> { async fn query_srv_record(hostname: &'_ str) -> Option<FedDest> {
let hostname = hostname.trim_end_matches('.'); let hostname = hostname.trim_end_matches('.');
@ -553,7 +556,7 @@ async fn query_srv_record(hostname: &'_ str) -> Option<FedDest> {
} }
} }
#[tracing::instrument(ret(level = "debug"))] #[t::instrument(ret(level = "debug"))]
async fn request_well_known(destination: &str) -> Option<String> { async fn request_well_known(destination: &str) -> Option<String> {
let response = services() let response = services()
.globals .globals
@ -561,13 +564,13 @@ async fn request_well_known(destination: &str) -> Option<String> {
.get(format!("https://{destination}/.well-known/matrix/server")) .get(format!("https://{destination}/.well-known/matrix/server"))
.send() .send()
.await; .await;
debug!("Got well known response"); t::debug!("Got well known response");
if let Err(error) = &response { if let Err(error) = &response {
debug!(%error, "Failed to request .well-known"); t::debug!(%error, "Failed to request .well-known");
return None; return None;
} }
let text = response.ok()?.text().await; 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()?; let body: serde_json::Value = serde_json::from_str(&text.ok()?).ok()?;
Some(body.get("m.server")?.as_str()?.to_owned()) 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( pub(crate) fn parse_incoming_pdu(
pdu: &RawJsonValue, pdu: &RawJsonValue,
) -> Result<(OwnedEventId, CanonicalJsonObject, OwnedRoomId)> { ) -> Result<(OwnedEventId, CanonicalJsonObject, OwnedRoomId)> {
let value: CanonicalJsonObject = let value: CanonicalJsonObject =
serde_json::from_str(pdu.get()).map_err(|error| { 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") Error::BadServerResponse("Invalid PDU in server response")
})?; })?;
@ -747,7 +750,7 @@ pub(crate) async fn send_transaction_message_route(
for pdu in &body.pdus { for pdu in &body.pdus {
let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) let value: CanonicalJsonObject = serde_json::from_str(pdu.get())
.map_err(|error| { .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") Error::BadServerResponse("Invalid PDU in server response")
})?; })?;
let room_id: OwnedRoomId = value let room_id: OwnedRoomId = value
@ -764,7 +767,7 @@ pub(crate) async fn send_transaction_message_route(
.get_create_content::<ExtractVersion>(&room_id) .get_create_content::<ExtractVersion>(&room_id)
.is_err() .is_err()
{ {
debug!(%room_id, "This server is not in the room"); t::debug!(%room_id, "This server is not in the room");
continue; continue;
} }
@ -772,7 +775,7 @@ pub(crate) async fn send_transaction_message_route(
let (event_id, value, room_id) = match r { let (event_id, value, room_id) = match r {
Ok(t) => t, Ok(t) => t,
Err(error) => { Err(error) => {
warn!(%error, object = ?pdu, "Error parsing incoming event"); t::warn!(%error, object = ?pdu, "Error parsing incoming event");
continue; continue;
} }
}; };
@ -803,7 +806,7 @@ pub(crate) async fn send_transaction_message_route(
); );
drop(federation_token); drop(federation_token);
debug!( t::debug!(
%event_id, %event_id,
elapsed = ?start_time.elapsed(), elapsed = ?start_time.elapsed(),
"Finished handling event", "Finished handling event",
@ -813,7 +816,7 @@ pub(crate) async fn send_transaction_message_route(
for pdu in &resolved_map { for pdu in &resolved_map {
if let (event_id, Err(error)) = pdu { if let (event_id, Err(error)) = pdu {
if matches!(error, Error::BadRequest(ErrorKind::NotFound, _)) { 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 (room_id, room_updates) in receipt.receipts {
for (user_id, user_updates) in room_updates.read { for (user_id, user_updates) in room_updates.read {
if user_id.server_name() != sender_servername { if user_id.server_name() != sender_servername {
warn!( t::warn!(
%user_id, %user_id,
%sender_servername, %sender_servername,
"Got receipt EDU from incorrect homeserver, \ "Got receipt EDU from incorrect homeserver, \
@ -874,7 +877,7 @@ pub(crate) async fn send_transaction_message_route(
)?; )?;
} else { } else {
// TODO fetch missing events // TODO fetch missing events
debug!( t::debug!(
?user_updates, ?user_updates,
"No known event ids in read receipt", "No known event ids in read receipt",
); );
@ -884,7 +887,7 @@ pub(crate) async fn send_transaction_message_route(
} }
Edu::Typing(typing) => { Edu::Typing(typing) => {
if typing.user_id.server_name() != sender_servername { if typing.user_id.server_name() != sender_servername {
warn!( t::warn!(
user_id = %typing.user_id, user_id = %typing.user_id,
%sender_servername, %sender_servername,
"Got typing EDU from incorrect homeserver, ignoring", "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 { if user_id.server_name() != sender_servername {
warn!( t::warn!(
%user_id, %user_id,
%sender_servername, %sender_servername,
"Got device list update EDU from incorrect homeserver, \ "Got device list update EDU from incorrect homeserver, \
@ -939,7 +942,7 @@ pub(crate) async fn send_transaction_message_route(
messages, messages,
}) => { }) => {
if sender.server_name() != sender_servername { if sender.server_name() != sender_servername {
warn!( t::warn!(
user_id = %sender, user_id = %sender,
%sender_servername, %sender_servername,
"Got direct-to-device EDU from incorrect homeserver, \ "Got direct-to-device EDU from incorrect homeserver, \
@ -965,7 +968,7 @@ pub(crate) async fn send_transaction_message_route(
&ev_type.to_string(), &ev_type.to_string(),
event.deserialize_as().map_err( event.deserialize_as().map_err(
|error| { |error| {
warn!( t::warn!(
%error, %error,
object = ?event.json(), object = ?event.json(),
"To-Device event is invalid", "To-Device event is invalid",
@ -1018,7 +1021,7 @@ pub(crate) async fn send_transaction_message_route(
self_signing_key, self_signing_key,
}) => { }) => {
if user_id.server_name() != sender_servername { if user_id.server_name() != sender_servername {
warn!( t::warn!(
%user_id, %user_id,
%sender_servername, %sender_servername,
"Got signing key update from incorrect homeserver, \ "Got signing key update from incorrect homeserver, \
@ -1063,7 +1066,7 @@ pub(crate) async fn get_event_route(
let event = let event =
services().rooms.timeline.get_pdu_json(&body.event_id)?.ok_or_else( 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.") Error::BadRequest(ErrorKind::NotFound, "Event not found.")
}, },
)?; )?;
@ -1116,7 +1119,7 @@ pub(crate) async fn get_backfill_route(
let sender_servername = let sender_servername =
body.sender_servername.as_ref().expect("server is authenticated"); 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() if !services()
.rooms .rooms
@ -1225,7 +1228,7 @@ pub(crate) async fn get_missing_events_route(
})?; })?;
if event_room_id != body.room_id { if event_room_id != body.room_id {
warn!( t::warn!(
event_id = %queued_events[i], event_id = %queued_events[i],
expected_room_id = %body.room_id, expected_room_id = %body.room_id,
actual_room_id = %event_room_id, actual_room_id = %event_room_id,
@ -1308,7 +1311,7 @@ pub(crate) async fn get_event_authorization_route(
let event = let event =
services().rooms.timeline.get_pdu_json(&body.event_id)?.ok_or_else( 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.") 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)) Some(PduEvent::convert_to_outgoing_federation_event(json))
} else { } else {
error!(%event_id, "Could not find event JSON for event"); t::error!(%event_id, "Could not find event JSON for event");
None None
} }
}) })
@ -1504,7 +1507,7 @@ pub(crate) async fn create_join_event_template_route(
.map(|join_rules_event| { .map(|join_rules_event| {
serde_json::from_str(join_rules_event.content.get()).map_err( serde_json::from_str(join_rules_event.content.get()).map_err(
|error| { |error| {
warn!(%error, "Invalid join rules event"); t::warn!(%error, "Invalid join rules event");
Error::bad_database("Invalid join rules event in db.") Error::bad_database("Invalid join rules event in db.")
}, },
) )
@ -1601,7 +1604,7 @@ async fn create_join_event(
.map(|join_rules_event| { .map(|join_rules_event| {
serde_json::from_str(join_rules_event.content.get()).map_err( serde_json::from_str(join_rules_event.content.get()).map_err(
|error| { |error| {
warn!(%error, "Invalid join rules event"); t::warn!(%error, "Invalid join rules event");
Error::bad_database("Invalid join rules event in db.") Error::bad_database("Invalid join rules event in db.")
}, },
) )
@ -1864,7 +1867,7 @@ pub(crate) async fn create_invite_route(
let pdu: PduEvent = let pdu: PduEvent =
serde_json::from_value(event.into()).map_err(|error| { 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.") 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| { let content_disposition = content_disposition.and_then(|s| {
s.parse().inspect_err( s.parse().inspect_err(
|error| warn!(%error, "Invalid Content-Disposition in database"), |error| t::warn!(%error, "Invalid Content-Disposition in database"),
) )
.ok() .ok()
}); });

6
src/cli/check_config.rs
View file

@ -1,12 +1,10 @@
use tracing::info; use crate::{cli::CheckConfigArgs, config, error, observability::prelude::*};
use crate::{cli::CheckConfigArgs, config, error};
pub(crate) async fn run( pub(crate) async fn run(
args: CheckConfigArgs, args: CheckConfigArgs,
) -> Result<(), error::CheckConfigCommand> { ) -> Result<(), error::CheckConfigCommand> {
let _config = let _config =
config::load(args.config.config.as_ref(), args.sandboxed).await?; config::load(args.config.config.as_ref(), args.sandboxed).await?;
info!("Configuration looks good"); t::info!("Configuration looks good");
Ok(()) Ok(())
} }

51
src/cli/serve.rs
View file

@ -46,7 +46,6 @@ use tower_http::{
trace::TraceLayer, trace::TraceLayer,
ServiceBuilderExt as _, ServiceBuilderExt as _,
}; };
use tracing::{debug, info, info_span, warn, Instrument};
use super::ServeArgs; use super::ServeArgs;
use crate::{ use crate::{
@ -58,7 +57,9 @@ use crate::{
}, },
config::{self, Config, ListenComponent, ListenConfig, ListenTransport}, config::{self, Config, ListenComponent, ListenConfig, ListenTransport},
database::KeyValueDatabase, database::KeyValueDatabase,
error, observability, services, set_application_state, error, observability,
observability::prelude::*,
services, set_application_state,
utils::{ utils::{
self, self,
error::{Error, Result}, error::{Error, Result},
@ -78,7 +79,7 @@ pub(crate) async fn run(args: ServeArgs) -> Result<(), error::ServeCommand> {
let (_guard, reload_handles) = observability::init(&config)?; let (_guard, reload_handles) = observability::init(&config)?;
info!("Loading database"); t::info!("Loading database");
let db = Box::leak(Box::new( let db = Box::leak(Box::new(
KeyValueDatabase::load_or_create(&config) KeyValueDatabase::load_or_create(&config)
.map_err(Error::DatabaseError)?, .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)?; db.apply_migrations().await.map_err(Error::DatabaseError)?;
info!("Starting background tasks"); t::info!("Starting background tasks");
services().admin.start_handler(); services().admin.start_handler();
services().sending.start_handler(); services().sending.start_handler();
KeyValueDatabase::start_cleanup_task(); KeyValueDatabase::start_cleanup_task();
services().globals.set_emergency_access(); services().globals.set_emergency_access();
info!("Starting server"); t::info!("Starting server");
run_server().await?; run_server().await?;
Ok(()) Ok(())
} }
#[tracing::instrument] #[t::instrument]
async fn federation_self_test() -> Result<()> { async fn federation_self_test() -> Result<()> {
let response = server_server::send_request( let response = server_server::send_request(
&services().globals.config.server_name, &services().globals.config.server_name,
@ -119,7 +120,7 @@ async fn federation_self_test() -> Result<()> {
.as_ref() .as_ref()
.is_none_or(|s| s.name.as_deref() != Some(env!("CARGO_PKG_NAME"))) .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( return Err(Error::BadConfig(
"Got unexpected version from our own version endpoint", "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), |h| h.proxied_address().map(|addr| addr.source),
); );
tracing::info_span!( t::info_span!(
"http_request", "http_request",
otel.name = format!("{method} {endpoint}"), otel.name = format!("{method} {endpoint}"),
%method, %method,
@ -320,21 +321,17 @@ async fn run_server() -> Result<(), error::Serve> {
), ),
) )
}) })
.on_request( .on_request(|request: &http::Request<_>, _span: &t::Span| {
|request: &http::Request<_>, _span: &tracing::Span| {
// can be enabled selectively using `filter = // can be enabled selectively using `filter =
// grapevine[incoming_request_curl]=trace` in config // grapevine[incoming_request_curl]=trace` in config
tracing::trace_span!("incoming_request_curl").in_scope( t::trace_span!("incoming_request_curl").in_scope(|| {
|| { t::trace!(
tracing::trace!(
cmd = utils::curlify(request), cmd = utils::curlify(request),
"curl command line for incoming request \ "curl command line for incoming request (guessed \
(guessed hostname)" hostname)"
); );
}, });
); }),
},
),
) )
.layer(axum::middleware::from_fn(unrecognized_method)) .layer(axum::middleware::from_fn(unrecognized_method))
.layer( .layer(
@ -372,7 +369,7 @@ async fn run_server() -> Result<(), error::Serve> {
} }
for listen in &config.listen { 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())?; spawner.spawn_server(listen.clone())?;
} }
@ -382,7 +379,7 @@ async fn run_server() -> Result<(), error::Serve> {
federation_self_test() federation_self_test()
.await .await
.map_err(error::Serve::FederationSelfTestFailed)?; .map_err(error::Serve::FederationSelfTestFailed)?;
debug!("Federation self-test completed successfully"); t::debug!("Federation self-test completed successfully");
} }
set_application_state(ApplicationState::Ready); set_application_state(ApplicationState::Ready);
@ -420,7 +417,7 @@ async fn unrecognized_method(
let uri = req.uri().clone(); let uri = req.uri().clone();
let inner = next.run(req).await; let inner = next.run(req).await;
if inner.status() == StatusCode::METHOD_NOT_ALLOWED { 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 { return Ok(Ra(UiaaResponse::MatrixError(RumaError {
body: ErrorBody::Standard { body: ErrorBody::Standard {
kind: ErrorKind::Unrecognized, kind: ErrorKind::Unrecognized,
@ -747,13 +744,13 @@ async fn handle_signals(
let sig = loop { let sig = loop {
tokio::select! { tokio::select! {
() = sighup() => { () = sighup() => {
info!("Received reload request"); t::info!("Received reload request");
set_application_state(ApplicationState::Reloading); set_application_state(ApplicationState::Reloading);
if let Some(tls_config) = tls_config.as_ref() { if let Some(tls_config) = tls_config.as_ref() {
if let Err(error) = reload_tls_config(tls_config).await { 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(); 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 { 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") Error::BadRequest(ErrorKind::Unrecognized, "Unrecognized request")
} }
@ -853,7 +850,7 @@ macro_rules! impl_ruma_handler {
on( on(
method_filter, method_filter,
|$( $ty: $ty, )* req: Ar<Req>| async move { |$( $ty: $ty, )* req: Ar<Req>| async move {
let span = info_span!( let span = t::info_span!(
"run_ruma_handler", "run_ruma_handler",
auth.user = ?req.sender_user, auth.user = ?req.sender_user,
auth.device = ?req.sender_device, auth.device = ?req.sender_device,

41
src/database.rs
View file

@ -11,10 +11,10 @@ use ruma::{
push::Ruleset, push::Ruleset,
EventId, OwnedRoomId, RoomId, UserId, EventId, OwnedRoomId, RoomId, UserId,
}; };
use tracing::{debug, error, info, info_span, warn, Instrument};
use crate::{ use crate::{
config::DatabaseBackend, config::DatabaseBackend,
observability::prelude::*,
service::{ service::{
media::MediaFileKey, media::MediaFileKey,
rooms::{ rooms::{
@ -258,7 +258,7 @@ impl KeyValueDatabase {
} }
if count > 1 { if count > 1 {
warn!("Multiple databases at database_path detected"); t::warn!("Multiple databases at database_path detected");
return Ok(()); return Ok(());
} }
@ -469,7 +469,7 @@ impl KeyValueDatabase {
let room_id = let room_id =
parts.next().expect("split always returns one element"); parts.next().expect("split always returns one element");
let Some(servername) = parts.next() else { let Some(servername) = parts.next() else {
error!("Migration: Invalid roomserverid in db."); t::error!("Migration: Invalid roomserverid in db.");
continue; continue;
}; };
let mut serverroomid = servername.to_vec(); let mut serverroomid = servername.to_vec();
@ -532,7 +532,7 @@ impl KeyValueDatabase {
if user.server_name() if user.server_name()
!= services().globals.server_name() != services().globals.server_name()
{ {
info!(?user, "Migration: creating user"); t::info!(?user, "Migration: creating user");
services().users.create(&user, None)?; services().users.create(&user, None)?;
} }
} }
@ -718,7 +718,7 @@ impl KeyValueDatabase {
let shortroomid = let shortroomid =
services().globals.next_count()?.to_be_bytes(); services().globals.next_count()?.to_be_bytes();
self.roomid_shortroomid.insert(&room_id, &shortroomid)?; self.roomid_shortroomid.insert(&room_id, &shortroomid)?;
info!("Migration: 8"); t::info!("Migration: 8");
} }
// Update pduids db layout // Update pduids db layout
let mut batch = self.pduid_pdu.iter().filter_map(|(key, v)| { let mut batch = self.pduid_pdu.iter().filter_map(|(key, v)| {
@ -799,10 +799,10 @@ impl KeyValueDatabase {
while iter.peek().is_some() { while iter.peek().is_some() {
self.tokenids self.tokenids
.insert_batch(&mut iter.by_ref().take(1000))?; .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 let batch2: Vec<_> = self
.tokenids .tokenids
@ -848,7 +848,7 @@ impl KeyValueDatabase {
) { ) {
Ok(u) => u, Ok(u) => u,
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
user_localpart = %username, user_localpart = %username,
"Invalid username", "Invalid username",
@ -950,7 +950,7 @@ impl KeyValueDatabase {
) { ) {
Ok(u) => u, Ok(u) => u,
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
user_localpart = %username, user_localpart = %username,
"Invalid username", "Invalid username",
@ -1002,7 +1002,7 @@ impl KeyValueDatabase {
"database should be migrated to the current version", "database should be migrated to the current version",
); );
info!( t::info!(
backend = %services().globals.config.database.backend, backend = %services().globals.config.database.backend,
version = latest_database_version, version = latest_database_version,
"Loaded database", "Loaded database",
@ -1015,7 +1015,7 @@ impl KeyValueDatabase {
// Create the admin room and server user on first run // Create the admin room and server user on first run
services().admin.create_admin_room().await?; services().admin.create_admin_room().await?;
info!( t::info!(
backend = %services().globals.config.database.backend, backend = %services().globals.config.database.backend,
version = latest_database_version, version = latest_database_version,
"Created new database", "Created new database",
@ -1025,7 +1025,7 @@ impl KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument] #[t::instrument]
pub(crate) fn start_cleanup_task() { pub(crate) fn start_cleanup_task() {
use std::time::{Duration, Instant}; use std::time::{Duration, Instant};
@ -1046,28 +1046,31 @@ impl KeyValueDatabase {
#[cfg(unix)] #[cfg(unix)]
let msg = tokio::select! { let msg = tokio::select! {
_ = i.tick() => || { _ = i.tick() => || {
debug!("cleanup: Timer ticked"); t::debug!("cleanup: Timer ticked");
}, },
_ = s.recv() => || { _ = s.recv() => || {
debug!("cleanup: Received SIGHUP"); t::debug!("cleanup: Received SIGHUP");
}, },
}; };
#[cfg(not(unix))] #[cfg(not(unix))]
let msg = { let msg = {
i.tick().await; i.tick().await;
|| debug!("cleanup: Timer ticked") || t::debug!("cleanup: Timer ticked")
}; };
async { async {
msg(); msg();
let start = Instant::now(); let start = Instant::now();
if let Err(error) = services().globals.cleanup() { if let Err(error) = services().globals.cleanup() {
error!(%error, "cleanup: Error"); t::error!(%error, "cleanup: Error");
} else { } 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; .await;
} }
}); });
@ -1084,7 +1087,7 @@ where
if current_version < new_version { if current_version < new_version {
migration()?; migration()?;
services().globals.bump_database_version(new_version)?; services().globals.bump_database_version(new_version)?;
warn!("Migration: {current_version} -> {new_version} finished"); t::warn!("Migration: {current_version} -> {new_version} finished");
} }
Ok(()) Ok(())
} }

23
src/database/abstraction/rocksdb.rs
View file

@ -10,12 +10,11 @@ use rocksdb::{
DBCompactionStyle, DBCompressionType, DBRecoveryMode, DBWithThreadMode, DBCompactionStyle, DBCompressionType, DBRecoveryMode, DBWithThreadMode,
Direction, IteratorMode, MultiThreaded, Options, ReadOptions, WriteOptions, Direction, IteratorMode, MultiThreaded, Options, ReadOptions, WriteOptions,
}; };
use tracing::Level;
use super::{ use super::{
super::Config, watchers::Watchers, KeyValueDatabaseEngine, KvTree, super::Config, watchers::Watchers, KeyValueDatabaseEngine, KvTree,
}; };
use crate::{utils, Result}; use crate::{observability::prelude::*, utils, Result};
pub(crate) struct Engine { pub(crate) struct Engine {
rocks: DBWithThreadMode<MultiThreaded>, rocks: DBWithThreadMode<MultiThreaded>,
@ -151,14 +150,14 @@ impl RocksDbEngineTree<'_> {
} }
impl KvTree for 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<Option<Vec<u8>>> { fn get(&self, key: &[u8]) -> Result<Option<Vec<u8>>> {
let readoptions = ReadOptions::default(); let readoptions = ReadOptions::default();
Ok(self.db.rocks.get_cf_opt(&self.cf(), key, &readoptions)?) 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<()> { fn insert(&self, key: &[u8], value: &[u8]) -> Result<()> {
let writeoptions = WriteOptions::default(); let writeoptions = WriteOptions::default();
let lock = self.write_lock.read().unwrap(); let lock = self.write_lock.read().unwrap();
@ -170,7 +169,7 @@ impl KvTree for RocksDbEngineTree<'_> {
Ok(()) Ok(())
} }
#[tracing::instrument(level = Level::TRACE, skip_all)] #[t::instrument(level = t::Level::TRACE, skip_all)]
fn insert_batch( fn insert_batch(
&self, &self,
iter: &mut dyn Iterator<Item = (Vec<u8>, Vec<u8>)>, iter: &mut dyn Iterator<Item = (Vec<u8>, Vec<u8>)>,
@ -183,13 +182,13 @@ impl KvTree for RocksDbEngineTree<'_> {
Ok(()) Ok(())
} }
#[tracing::instrument(level = Level::TRACE, skip_all)] #[t::instrument(level = t::Level::TRACE, skip_all)]
fn remove(&self, key: &[u8]) -> Result<()> { fn remove(&self, key: &[u8]) -> Result<()> {
let writeoptions = WriteOptions::default(); let writeoptions = WriteOptions::default();
Ok(self.db.rocks.delete_cf_opt(&self.cf(), key, &writeoptions)?) 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<dyn Iterator<Item = (Vec<u8>, Vec<u8>)> + 'a> { fn iter<'a>(&'a self) -> Box<dyn Iterator<Item = (Vec<u8>, Vec<u8>)> + 'a> {
let readoptions = ReadOptions::default(); 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>( fn iter_from<'a>(
&'a self, &'a self,
from: &[u8], 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<Vec<u8>> { fn increment(&self, key: &[u8]) -> Result<Vec<u8>> {
let readoptions = ReadOptions::default(); let readoptions = ReadOptions::default();
let writeoptions = WriteOptions::default(); let writeoptions = WriteOptions::default();
@ -245,7 +244,7 @@ impl KvTree for RocksDbEngineTree<'_> {
Ok(new) Ok(new)
} }
#[tracing::instrument(level = Level::TRACE, skip_all)] #[t::instrument(level = t::Level::TRACE, skip_all)]
fn increment_batch( fn increment_batch(
&self, &self,
iter: &mut dyn Iterator<Item = Vec<u8>>, iter: &mut dyn Iterator<Item = Vec<u8>>,
@ -267,7 +266,7 @@ impl KvTree for RocksDbEngineTree<'_> {
Ok(()) Ok(())
} }
#[tracing::instrument(level = Level::TRACE, skip_all)] #[t::instrument(level = t::Level::TRACE, skip_all)]
fn scan_prefix<'a>( fn scan_prefix<'a>(
&'a self, &'a self,
prefix: Vec<u8>, prefix: Vec<u8>,
@ -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>( fn watch_prefix<'a>(
&'a self, &'a self,
prefix: &[u8], prefix: &[u8],

7
src/database/abstraction/sqlite.rs
View file

@ -9,10 +9,9 @@ use std::{
use parking_lot::{Mutex, MutexGuard}; use parking_lot::{Mutex, MutexGuard};
use rusqlite::{Connection, DatabaseName::Main, OptionalExtension}; use rusqlite::{Connection, DatabaseName::Main, OptionalExtension};
use thread_local::ThreadLocal; use thread_local::ThreadLocal;
use tracing::debug;
use super::{watchers::Watchers, KeyValueDatabaseEngine, KvTree}; use super::{watchers::Watchers, KeyValueDatabaseEngine, KvTree};
use crate::{database::Config, Result}; use crate::{database::Config, observability::prelude::*, Result};
thread_local! { thread_local! {
static READ_CONNECTION: RefCell<Option<&'static Connection>> = static READ_CONNECTION: RefCell<Option<&'static Connection>> =
@ -397,11 +396,11 @@ impl KvTree for SqliteTable {
} }
fn clear(&self) -> Result<()> { fn clear(&self) -> Result<()> {
debug!("clear: running"); t::debug!("clear: running");
self.engine self.engine
.write_lock() .write_lock()
.execute(format!("DELETE FROM {}", self.name).as_str(), [])?; .execute(format!("DELETE FROM {}", self.name).as_str(), [])?;
debug!("clear: ran"); t::debug!("clear: ran");
Ok(()) Ok(())
} }
} }

9
src/database/key_value/account_data.rs
View file

@ -8,13 +8,14 @@ use ruma::{
}; };
use crate::{ 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 { impl service::account_data::Data for KeyValueDatabase {
/// Places one event in the account data of the user and removes the /// Places one event in the account data of the user and removes the
/// previous entry. /// 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( fn update(
&self, &self,
room_id: Option<&RoomId>, room_id: Option<&RoomId>,
@ -66,7 +67,7 @@ impl service::account_data::Data for KeyValueDatabase {
} }
/// Searches the account data for a specific kind. /// 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( fn get(
&self, &self,
room_id: Option<&RoomId>, 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`. /// 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( fn changes_since(
&self, &self,
room_id: Option<&RoomId>, room_id: Option<&RoomId>,

3
src/database/key_value/globals.rs
View file

@ -8,6 +8,7 @@ use ruma::{
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{self, globals::SigningKeys}, service::{self, globals::SigningKeys},
services, utils, Error, Result, 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( async fn watch(
&self, &self,
user_id: &UserId, user_id: &UserId,

3
src/database/key_value/media.rs
View file

@ -2,6 +2,7 @@ use ruma::OwnedMxcUri;
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{ service::{
self, self,
media::{FileMeta, MediaFileKey}, media::{FileMeta, MediaFileKey},
@ -20,7 +21,7 @@ struct MediaFileKeyParts {
impl TryFrom<&MediaFileKey> for MediaFileKeyParts { impl TryFrom<&MediaFileKey> for MediaFileKeyParts {
type Error = Error; type Error = Error;
#[tracing::instrument( #[t::instrument(
err, err,
fields(key = utils::u8_slice_to_hex(key.as_bytes())), fields(key = utils::u8_slice_to_hex(key.as_bytes())),
)] )]

11
src/database/key_value/rooms/alias.rs
View file

@ -4,11 +4,12 @@ use ruma::{
}; };
use crate::{ 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 { 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<()> { fn set_alias(&self, alias: &RoomAliasId, room_id: &RoomId) -> Result<()> {
self.alias_roomid self.alias_roomid
.insert(alias.alias().as_bytes(), room_id.as_bytes())?; .insert(alias.alias().as_bytes(), room_id.as_bytes())?;
@ -20,7 +21,7 @@ impl service::rooms::alias::Data for KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn remove_alias(&self, alias: &RoomAliasId) -> Result<()> { fn remove_alias(&self, alias: &RoomAliasId) -> Result<()> {
if let Some(room_id) = if let Some(room_id) =
self.alias_roomid.get(alias.alias().as_bytes())? self.alias_roomid.get(alias.alias().as_bytes())?
@ -41,7 +42,7 @@ impl service::rooms::alias::Data for KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn resolve_local_alias( fn resolve_local_alias(
&self, &self,
alias: &RoomAliasId, alias: &RoomAliasId,
@ -63,7 +64,7 @@ impl service::rooms::alias::Data for KeyValueDatabase {
.transpose() .transpose()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn local_aliases_for_room<'a>( fn local_aliases_for_room<'a>(
&'a self, &'a self,
room_id: &RoomId, room_id: &RoomId,

3
src/database/key_value/rooms/auth_chain.rs
View file

@ -2,12 +2,13 @@ use std::{collections::HashSet, mem::size_of};
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{self, rooms::short::ShortEventId}, service::{self, rooms::short::ShortEventId},
utils, Result, utils, Result,
}; };
impl service::rooms::auth_chain::Data for KeyValueDatabase { impl service::rooms::auth_chain::Data for KeyValueDatabase {
#[tracing::instrument(skip(self, key))] #[t::instrument(skip(self, key))]
fn get_cached_eventid_authchain( fn get_cached_eventid_authchain(
&self, &self,
key: &[ShortEventId], key: &[ShortEventId],

13
src/database/key_value/rooms/directory.rs
View file

@ -1,24 +1,27 @@
use ruma::{OwnedRoomId, RoomId}; 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 { impl service::rooms::directory::Data for KeyValueDatabase {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn set_public(&self, room_id: &RoomId) -> Result<()> { fn set_public(&self, room_id: &RoomId) -> Result<()> {
self.publicroomids.insert(room_id.as_bytes(), &[]) self.publicroomids.insert(room_id.as_bytes(), &[])
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn set_not_public(&self, room_id: &RoomId) -> Result<()> { fn set_not_public(&self, room_id: &RoomId) -> Result<()> {
self.publicroomids.remove(room_id.as_bytes()) self.publicroomids.remove(room_id.as_bytes())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn is_public_room(&self, room_id: &RoomId) -> Result<bool> { fn is_public_room(&self, room_id: &RoomId) -> Result<bool> {
Ok(self.publicroomids.get(room_id.as_bytes())?.is_some()) Ok(self.publicroomids.get(room_id.as_bytes())?.is_some())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn public_rooms<'a>( fn public_rooms<'a>(
&'a self, &'a self,
) -> Box<dyn Iterator<Item = Result<OwnedRoomId>> + 'a> { ) -> Box<dyn Iterator<Item = Result<OwnedRoomId>> + 'a> {

11
src/database/key_value/rooms/edus/read_receipt.rs
View file

@ -4,11 +4,12 @@ use ruma::{
}; };
use crate::{ 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 { impl service::rooms::edus::read_receipt::Data for KeyValueDatabase {
#[tracing::instrument(skip(self, event))] #[t::instrument(skip(self, event))]
fn readreceipt_update( fn readreceipt_update(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -52,7 +53,7 @@ impl service::rooms::edus::read_receipt::Data for KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
fn readreceipts_since<'a>( fn readreceipts_since<'a>(
&'a self, &'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( fn private_read_set(
&self, &self,
room_id: &RoomId, 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()) .insert(&key, &services().globals.next_count()?.to_be_bytes())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn private_read_get( fn private_read_get(
&self, &self,
room_id: &RoomId, room_id: &RoomId,

5
src/database/key_value/rooms/metadata.rs
View file

@ -1,11 +1,12 @@
use ruma::{OwnedRoomId, RoomId}; use ruma::{OwnedRoomId, RoomId};
use crate::{ 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 { impl service::rooms::metadata::Data for KeyValueDatabase {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn exists(&self, room_id: &RoomId) -> Result<bool> { fn exists(&self, room_id: &RoomId) -> Result<bool> {
let prefix = match services().rooms.short.get_shortroomid(room_id)? { let prefix = match services().rooms.short.get_shortroomid(room_id)? {
Some(b) => b.get().to_be_bytes().to_vec(), Some(b) => b.get().to_be_bytes().to_vec(),

7
src/database/key_value/rooms/outlier.rs
View file

@ -1,6 +1,9 @@
use ruma::{CanonicalJsonObject, EventId}; 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 { impl service::rooms::outlier::Data for KeyValueDatabase {
fn get_outlier_pdu_json( 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( fn add_pdu_outlier(
&self, &self,
event_id: &EventId, event_id: &EventId,

7
src/database/key_value/rooms/search.rs
View file

@ -2,6 +2,7 @@ use ruma::RoomId;
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{ service::{
self, self,
rooms::{short::ShortRoomId, timeline::PduId}, rooms::{short::ShortRoomId, timeline::PduId},
@ -21,7 +22,7 @@ fn tokenize(body: &str) -> impl Iterator<Item = String> + '_ {
} }
impl service::rooms::search::Data for KeyValueDatabase { impl service::rooms::search::Data for KeyValueDatabase {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn index_pdu( fn index_pdu(
&self, &self,
shortroomid: ShortRoomId, shortroomid: ShortRoomId,
@ -40,7 +41,7 @@ impl service::rooms::search::Data for KeyValueDatabase {
self.tokenids.insert_batch(&mut batch) self.tokenids.insert_batch(&mut batch)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn deindex_pdu( fn deindex_pdu(
&self, &self,
shortroomid: ShortRoomId, shortroomid: ShortRoomId,
@ -63,7 +64,7 @@ impl service::rooms::search::Data for KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
fn search_pdus<'a>( fn search_pdus<'a>(
&'a self, &'a self,

13
src/database/key_value/rooms/short.rs
View file

@ -4,6 +4,7 @@ use ruma::{events::StateEventType, EventId, RoomId};
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{ service::{
self, self,
rooms::short::{ rooms::short::{
@ -14,7 +15,7 @@ use crate::{
}; };
impl service::rooms::short::Data for KeyValueDatabase { impl service::rooms::short::Data for KeyValueDatabase {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_or_create_shorteventid( fn get_or_create_shorteventid(
&self, &self,
event_id: &EventId, event_id: &EventId,
@ -40,7 +41,7 @@ impl service::rooms::short::Data for KeyValueDatabase {
Ok((ShortEventId::new(short), created)) Ok((ShortEventId::new(short), created))
} }
#[tracing::instrument(skip(self), fields(cache_result))] #[t::instrument(skip(self), fields(cache_result))]
fn get_shortstatekey( fn get_shortstatekey(
&self, &self,
event_type: &StateEventType, event_type: &StateEventType,
@ -65,7 +66,7 @@ impl service::rooms::short::Data for KeyValueDatabase {
Ok(short) Ok(short)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_or_create_shortstatekey( fn get_or_create_shortstatekey(
&self, &self,
event_type: &StateEventType, event_type: &StateEventType,
@ -98,7 +99,7 @@ impl service::rooms::short::Data for KeyValueDatabase {
Ok((short, created)) Ok((short, created))
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_eventid_from_short( fn get_eventid_from_short(
&self, &self,
shorteventid: ShortEventId, shorteventid: ShortEventId,
@ -124,7 +125,7 @@ impl service::rooms::short::Data for KeyValueDatabase {
Ok(event_id) Ok(event_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_statekey_from_short( fn get_statekey_from_short(
&self, &self,
shortstatekey: ShortStateKey, shortstatekey: ShortStateKey,
@ -162,7 +163,7 @@ impl service::rooms::short::Data for KeyValueDatabase {
} }
/// Returns `(shortstatehash, already_existed)` /// Returns `(shortstatehash, already_existed)`
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_or_create_shortstatehash( fn get_or_create_shortstatehash(
&self, &self,
state_hash: &[u8], state_hash: &[u8],

41
src/database/key_value/rooms/state_cache.rs
View file

@ -8,6 +8,7 @@ use ruma::{
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{self, appservice::RegistrationInfo}, service::{self, appservice::RegistrationInfo},
services, utils, Error, Result, services, utils, Error, Result,
}; };
@ -166,7 +167,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
Ok(real_users) Ok(real_users)
} }
#[tracing::instrument( #[t::instrument(
skip(self, appservice), skip(self, appservice),
fields(appservice_id = appservice.registration.id), fields(appservice_id = appservice.registration.id),
)] )]
@ -193,7 +194,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
} }
/// Makes a user forget a room. /// Makes a user forget a room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn forget(&self, room_id: &RoomId, user_id: &UserId) -> Result<()> { fn forget(&self, room_id: &RoomId, user_id: &UserId) -> Result<()> {
let mut userroom_id = user_id.as_bytes().to_vec(); let mut userroom_id = user_id.as_bytes().to_vec();
userroom_id.push(0xFF); 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. /// Returns an iterator of all servers participating in this room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn room_servers<'a>( fn room_servers<'a>(
&'a self, &'a self,
room_id: &RoomId, 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( fn server_in_room(
&self, &self,
server: &ServerName, 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 /// Returns an iterator of all rooms a server participates in (as far as we
/// know). /// know).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn server_rooms<'a>( fn server_rooms<'a>(
&'a self, &'a self,
server: &ServerName, server: &ServerName,
@ -280,7 +281,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
} }
/// Returns an iterator over all joined members of a room. /// Returns an iterator over all joined members of a room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn room_members<'a>( fn room_members<'a>(
&'a self, &'a self,
room_id: &RoomId, 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<Option<u64>> { fn room_joined_count(&self, room_id: &RoomId) -> Result<Option<u64>> {
self.roomid_joinedcount self.roomid_joinedcount
.get(room_id.as_bytes())? .get(room_id.as_bytes())?
@ -319,7 +320,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
.transpose() .transpose()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn room_invited_count(&self, room_id: &RoomId) -> Result<Option<u64>> { fn room_invited_count(&self, room_id: &RoomId) -> Result<Option<u64>> {
self.roomid_invitedcount self.roomid_invitedcount
.get(room_id.as_bytes())? .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. /// Returns an iterator over all invited members of a room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn room_members_invited<'a>( fn room_members_invited<'a>(
&'a self, &'a self,
room_id: &RoomId, 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( fn get_invite_count(
&self, &self,
room_id: &RoomId, 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( fn get_left_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -401,7 +402,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
} }
/// Returns an iterator over all rooms this user joined. /// Returns an iterator over all rooms this user joined.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn rooms_joined<'a>( fn rooms_joined<'a>(
&'a self, &'a self,
user_id: &UserId, 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. /// Returns an iterator over all rooms a user was invited to.
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn rooms_invited<'a>( fn rooms_invited<'a>(
&'a self, &'a self,
user_id: &UserId, 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( fn invite_state(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -501,7 +502,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
.transpose() .transpose()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn left_state( fn left_state(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -527,7 +528,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
/// Returns an iterator over all rooms a user left. /// Returns an iterator over all rooms a user left.
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn rooms_left<'a>( fn rooms_left<'a>(
&'a self, &'a self,
user_id: &UserId, 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<bool> { fn once_joined(&self, user_id: &UserId, room_id: &RoomId) -> Result<bool> {
let mut userroom_id = user_id.as_bytes().to_vec(); let mut userroom_id = user_id.as_bytes().to_vec();
userroom_id.push(0xFF); userroom_id.push(0xFF);
@ -578,7 +579,7 @@ impl service::rooms::state_cache::Data for KeyValueDatabase {
Ok(self.roomuseroncejoinedids.get(&userroom_id)?.is_some()) 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<bool> { fn is_joined(&self, user_id: &UserId, room_id: &RoomId) -> Result<bool> {
let mut userroom_id = user_id.as_bytes().to_vec(); let mut userroom_id = user_id.as_bytes().to_vec();
userroom_id.push(0xFF); 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()) 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<bool> { fn is_invited(&self, user_id: &UserId, room_id: &RoomId) -> Result<bool> {
let mut userroom_id = user_id.as_bytes().to_vec(); let mut userroom_id = user_id.as_bytes().to_vec();
userroom_id.push(0xFF); 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()) 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<bool> { fn is_left(&self, user_id: &UserId, room_id: &RoomId) -> Result<bool> {
let mut userroom_id = user_id.as_bytes().to_vec(); let mut userroom_id = user_id.as_bytes().to_vec();
userroom_id.push(0xFF); userroom_id.push(0xFF);

3
src/database/key_value/rooms/timeline.rs
View file

@ -8,6 +8,7 @@ use service::rooms::timeline::PduCount;
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{self, rooms::timeline::PduId}, service::{self, rooms::timeline::PduId},
services, utils, Error, PduEvent, Result, services, utils, Error, PduEvent, Result,
}; };
@ -89,7 +90,7 @@ impl service::rooms::timeline::Data for KeyValueDatabase {
/// Returns the pdu. /// Returns the pdu.
/// ///
/// Checks the `eventid_outlierpdu` Tree if not found in the timeline. /// 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<Option<Arc<PduEvent>>> { fn get_pdu(&self, event_id: &EventId) -> Result<Option<Arc<PduEvent>>> {
Ok(self Ok(self
.get_non_outlier_pdu(event_id)? .get_non_outlier_pdu(event_id)?

3
src/database/key_value/sending.rs
View file

@ -2,6 +2,7 @@ use ruma::{serde::Raw, ServerName, UserId};
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{ service::{
self, self,
rooms::timeline::PduId, 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( fn parse_servercurrentevent(
key: &RequestKey, key: &RequestKey,
value: Vec<u8>, value: Vec<u8>,

14
src/database/key_value/users.rs
View file

@ -9,10 +9,10 @@ use ruma::{
OwnedDeviceId, OwnedKeyId, OwnedMxcUri, OwnedOneTimeKeyId, OwnedUserId, OwnedDeviceId, OwnedKeyId, OwnedMxcUri, OwnedOneTimeKeyId, OwnedUserId,
UInt, UserId, UInt, UserId,
}; };
use tracing::warn;
use crate::{ use crate::{
database::KeyValueDatabase, database::KeyValueDatabase,
observability::prelude::*,
service::{self, users::clean_signatures}, service::{self, users::clean_signatures},
services, utils, Error, Result, services, utils, Error, Result,
}; };
@ -490,7 +490,7 @@ impl service::users::Data for KeyValueDatabase {
Ok(counts) Ok(counts)
} }
#[tracing::instrument(skip(self, device_keys))] #[t::instrument(skip(self, device_keys))]
fn add_device_keys( fn add_device_keys(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -512,7 +512,7 @@ impl service::users::Data for KeyValueDatabase {
Ok(()) Ok(())
} }
#[tracing::instrument(skip( #[t::instrument(skip(
self, self,
master_key, master_key,
self_signing_key, self_signing_key,
@ -700,14 +700,14 @@ impl service::users::Data for KeyValueDatabase {
if let Ok(c) = utils::u64_from_bytes(current) { if let Ok(c) = utils::u64_from_bytes(current) {
c <= to c <= to
} else { } else {
warn!( t::warn!(
"BadDatabase: Could not parse \ "BadDatabase: Could not parse \
keychangeid_userid bytes" keychangeid_userid bytes"
); );
false false
} }
} else { } else {
warn!( t::warn!(
"BadDatabase: Could not parse \ "BadDatabase: Could not parse \
keychangeid_userid" 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<()> { fn mark_device_key_update(&self, user_id: &UserId) -> Result<()> {
let count = services().globals.next_count()?.to_be_bytes(); let count = services().globals.next_count()?.to_be_bytes();
for room_id in services() for room_id in services()
@ -1102,7 +1102,7 @@ fn get_username_with_valid_password(
match utils::string_from_bytes(username) { match utils::string_from_bytes(username) {
Ok(u) => Some(u), Ok(u) => Some(u),
Err(e) => { Err(e) => {
warn!( t::warn!(
"Failed to parse username while calling \ "Failed to parse username while calling \
get_local_users(): {}", get_local_users(): {}",
e.to_string() e.to_string()

6
src/error.rs
View file

@ -4,7 +4,7 @@ use std::path::PathBuf;
use thiserror::Error; use thiserror::Error;
use crate::config::ListenConfig; use crate::{config::ListenConfig, observability::prelude::*};
/// Top-level errors /// Top-level errors
// Missing docs are allowed here since that kind of information should be // Missing docs are allowed here since that kind of information should be
@ -16,7 +16,7 @@ pub(crate) enum Main {
ServeCommand(#[from] ServeCommand), ServeCommand(#[from] ServeCommand),
#[error("failed to install global default tracing subscriber")] #[error("failed to install global default tracing subscriber")]
SetSubscriber(#[from] tracing::subscriber::SetGlobalDefaultError), SetSubscriber(#[from] t::subscriber::SetGlobalDefaultError),
#[error(transparent)] #[error(transparent)]
CheckConfigCommand(#[from] CheckConfigCommand), CheckConfigCommand(#[from] CheckConfigCommand),
@ -84,7 +84,7 @@ pub(crate) enum Observability {
Otel(#[from] opentelemetry::trace::TraceError), Otel(#[from] opentelemetry::trace::TraceError),
#[error("failed to install global default tracing subscriber")] #[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 // Upstream's documentation on what this error means is very sparse
#[error("tracing_flame error")] #[error("tracing_flame error")]

12
src/main.rs
View file

@ -7,9 +7,10 @@ use std::process::ExitCode;
use clap::Parser; use clap::Parser;
#[cfg(all(not(target_env = "msvc"), feature = "jemalloc"))] #[cfg(all(not(target_env = "msvc"), feature = "jemalloc"))]
use tikv_jemallocator::Jemalloc; use tikv_jemallocator::Jemalloc;
use tracing::{error, info};
use wee_woo::ErrorExt; use wee_woo::ErrorExt;
use crate::observability::prelude::*;
mod api; mod api;
mod cli; mod cli;
mod config; mod config;
@ -50,7 +51,7 @@ enum ApplicationState {
} }
fn set_application_state(state: ApplicationState) { fn set_application_state(state: ApplicationState) {
info!(?state, "Application state changed"); t::info!(?state, "Application state changed");
#[cfg(feature = "systemd")] #[cfg(feature = "systemd")]
{ {
@ -107,20 +108,19 @@ async fn main() -> ExitCode {
} }
#[cfg(unix)] #[cfg(unix)]
#[tracing::instrument(err)] #[t::instrument(err)]
fn maximize_fd_limit() -> Result<(), nix::errno::Errno> { fn maximize_fd_limit() -> Result<(), nix::errno::Errno> {
use nix::sys::resource::{getrlimit, setrlimit, Resource}; use nix::sys::resource::{getrlimit, setrlimit, Resource};
use tracing::debug;
let res = Resource::RLIMIT_NOFILE; let res = Resource::RLIMIT_NOFILE;
let (soft_limit, hard_limit) = getrlimit(res)?; 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)?; 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(()) Ok(())
} }

11
src/observability.rs
View file

@ -23,7 +23,7 @@ use opentelemetry_sdk::{
use strum::{AsRefStr, IntoStaticStr}; use strum::{AsRefStr, IntoStaticStr};
use thiserror::Error; use thiserror::Error;
use tokio::time::Instant; use tokio::time::Instant;
use tracing::{subscriber::SetGlobalDefaultError, Span}; use tracing::subscriber::SetGlobalDefaultError;
use tracing_flame::{FlameLayer, FlushGuard}; use tracing_flame::{FlameLayer, FlushGuard};
use tracing_opentelemetry::OtelData; use tracing_opentelemetry::OtelData;
use tracing_subscriber::{ use tracing_subscriber::{
@ -35,6 +35,7 @@ use tracing_subscriber::{
use crate::{ use crate::{
config::{Config, EnvFilterClone, LogFormat}, config::{Config, EnvFilterClone, LogFormat},
error, error,
observability::prelude::*,
utils::error::Result, utils::error::Result,
}; };
@ -314,7 +315,7 @@ pub(crate) fn init(
.with(traces_layer) .with(traces_layer)
.with(flame_layer) .with(flame_layer)
.with(log_layer); .with(log_layer);
tracing::subscriber::set_global_default(subscriber)?; t::subscriber::set_global_default(subscriber)?;
Ok(( Ok((
Guard { 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 { pub(crate) async fn traceresponse_layer(req: Request, next: Next) -> Response {
let mut resp = next.run(req).await; let mut resp = next.run(req).await;
let ids = tracing::dispatcher::get_default(|dispatch| { let ids = t::dispatcher::get_default(|dispatch| {
Span::current() t::Span::current()
.id() .id()
.and_then(|id| { .and_then(|id| {
dispatch dispatch
@ -557,5 +558,5 @@ pub(crate) fn init_for_cli(
let subscriber = Registry::default().with(log_layer); 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)
} }

1
src/observability/prelude.rs
View file

@ -8,7 +8,6 @@
//! This avoids diff churn in the imports when adding/removing log statements. //! This avoids diff churn in the imports when adding/removing log statements.
//! //!
//! [`tracing`] is re-exported as `t`, to avoid name collisions. //! [`tracing`] is re-exported as `t`, to avoid name collisions.
#![allow(unused)]
pub(crate) use tracing as t; pub(crate) use tracing as t;
pub(crate) use tracing::Instrument; pub(crate) use tracing::Instrument;

26
src/service/admin.rs
View file

@ -28,11 +28,11 @@ use ruma::{
}; };
use serde_json::value::to_raw_value; use serde_json::value::to_raw_value;
use tokio::sync::{mpsc, Mutex, RwLock}; use tokio::sync::{mpsc, Mutex, RwLock};
use tracing::warn;
use super::pdu::PduBuilder; use super::pdu::PduBuilder;
use crate::{ use crate::{
api::client_server::{leave_all_rooms, AUTO_GEN_PASSWORD_LENGTH}, api::client_server::{leave_all_rooms, AUTO_GEN_PASSWORD_LENGTH},
observability::prelude::*,
services, services,
utils::{self, dbg_truncate_str, room_version::RoomVersion}, utils::{self, dbg_truncate_str, room_version::RoomVersion},
Error, PduEvent, Result, 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( async fn handle_event(
&self, &self,
event: AdminRoomEvent, event: AdminRoomEvent,
@ -327,7 +327,7 @@ impl Service {
.unwrap(); .unwrap();
} }
#[tracing::instrument( #[t::instrument(
skip(self, room_message), skip(self, room_message),
fields( fields(
room_message = dbg_truncate_str(&room_message, 50).as_ref(), room_message = dbg_truncate_str(&room_message, 50).as_ref(),
@ -337,7 +337,7 @@ impl Service {
self.sender.send(AdminRoomEvent::ProcessMessage(room_message)).unwrap(); 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( pub(crate) fn send_message(
&self, &self,
message_content: RoomMessageEventContent, message_content: RoomMessageEventContent,
@ -346,7 +346,7 @@ impl Service {
} }
// Parse and process a message from the admin room // Parse and process a message from the admin room
#[tracing::instrument( #[t::instrument(
skip(self, room_message), skip(self, room_message),
fields( fields(
room_message = dbg_truncate_str(&room_message, 50).as_ref(), 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 // Parse chat messages from the admin room into an AdminCommand object
#[tracing::instrument( #[t::instrument(
skip(command_line), skip(command_line),
fields( fields(
command_line = dbg_truncate_str(command_line, 50).as_ref(), command_line = dbg_truncate_str(command_line, 50).as_ref(),
@ -428,7 +428,7 @@ impl Service {
} }
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument(skip(self, body))] #[t::instrument(skip(self, body))]
async fn process_admin_command( async fn process_admin_command(
&self, &self,
command: AdminCommand, command: AdminCommand,
@ -1068,7 +1068,11 @@ impl Service {
if leave_rooms { if leave_rooms {
for &user_id in &user_ids { for &user_id in &user_ids {
if let Err(error) = leave_all_rooms(user_id).await { 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. // 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 { fn usage_to_html(text: &str, server_name: &ServerName) -> String {
// Replace `@grapevine:servername:-subcmdname` with // Replace `@grapevine:servername:-subcmdname` with
// `@grapevine:servername: subcmdname` // `@grapevine:servername: subcmdname`
@ -1334,7 +1338,7 @@ impl Service {
/// be used to issue admin commands by talking to the server user inside /// be used to issue admin commands by talking to the server user inside
/// it. /// it.
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn create_admin_room(&self) -> Result<()> { pub(crate) async fn create_admin_room(&self) -> Result<()> {
let room_id = RoomId::new(services().globals.server_name()); let room_id = RoomId::new(services().globals.server_name());
@ -1586,7 +1590,7 @@ impl Service {
/// Invite the user to the grapevine admin room. /// Invite the user to the grapevine admin room.
/// ///
/// In grapevine, this is equivalent to granting admin privileges. /// In grapevine, this is equivalent to granting admin privileges.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn make_user_admin( pub(crate) async fn make_user_admin(
&self, &self,
user_id: &UserId, user_id: &UserId,

14
src/service/appservice.rs
View file

@ -8,7 +8,7 @@ use ruma::{
}; };
use tokio::sync::RwLock; use tokio::sync::RwLock;
use crate::Result; use crate::{observability::prelude::*, Result};
mod data; mod data;
@ -137,7 +137,7 @@ impl Service {
} }
/// Registers an appservice and returns the ID to the caller. /// 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( pub(crate) async fn register_appservice(
&self, &self,
yaml: Registration, yaml: Registration,
@ -156,7 +156,7 @@ impl Service {
/// # Arguments /// # Arguments
/// ///
/// * `service_name` - the name you send to register the service previously /// * `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( pub(crate) async fn unregister_appservice(
&self, &self,
service_name: &str, service_name: &str,
@ -168,7 +168,7 @@ impl Service {
self.db.unregister_appservice(service_name) self.db.unregister_appservice(service_name)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn get_registration( pub(crate) async fn get_registration(
&self, &self,
id: &str, id: &str,
@ -185,7 +185,7 @@ impl Service {
self.registration_info.read().await.keys().cloned().collect() self.registration_info.read().await.keys().cloned().collect()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn find_from_token( pub(crate) async fn find_from_token(
&self, &self,
token: &str, token: &str,
@ -198,7 +198,7 @@ impl Service {
} }
// Checks if a given user id matches any exclusive appservice regex // 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 { pub(crate) async fn is_exclusive_user_id(&self, user_id: &UserId) -> bool {
self.read() self.read()
.await .await
@ -207,7 +207,7 @@ impl Service {
} }
// Checks if a given room alias matches any exclusive appservice regex // 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 { pub(crate) async fn is_exclusive_alias(&self, alias: &RoomAliasId) -> bool {
self.read() self.read()
.await .await

26
src/service/globals.rs
View file

@ -34,13 +34,12 @@ use ruma::{
ServerName, UInt, UserId, ServerName, UInt, UserId,
}; };
use tokio::sync::{broadcast, Mutex, RwLock, Semaphore}; use tokio::sync::{broadcast, Mutex, RwLock, Semaphore};
use tracing::{error, warn, Instrument};
use trust_dns_resolver::TokioAsyncResolver; use trust_dns_resolver::TokioAsyncResolver;
use crate::{ use crate::{
api::server_server::FedDest, api::server_server::FedDest,
config::{MediaBackendConfig, MediaFilesystemConfig}, config::{MediaBackendConfig, MediaFilesystemConfig},
observability::FilterReloadHandles, observability::{prelude::*, FilterReloadHandles},
service::media::MediaFileKey, service::media::MediaFileKey,
services, services,
utils::on_demand_hashmap::{OnDemandHashMap, TokenSet}, utils::on_demand_hashmap::{OnDemandHashMap, TokenSet},
@ -156,7 +155,7 @@ impl Resolver {
} }
impl Resolve for Resolver { impl Resolve for Resolver {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn resolve(&self, name: Name) -> Resolving { fn resolve(&self, name: Name) -> Resolving {
self.overrides self.overrides
.read() .read()
@ -197,7 +196,7 @@ impl Resolve for Resolver {
} }
impl Service { impl Service {
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
pub(crate) fn new( pub(crate) fn new(
db: &'static dyn Data, db: &'static dyn Data,
config: Config, config: Config,
@ -208,7 +207,7 @@ impl Service {
let keypair = match keypair { let keypair = match keypair {
Ok(k) => k, Ok(k) => k,
Err(e) => { Err(e) => {
error!("Keypair invalid. Deleting..."); t::error!("Keypair invalid. Deleting...");
db.remove_keypair()?; db.remove_keypair()?;
return Err(e); return Err(e);
} }
@ -257,7 +256,7 @@ impl Service {
keypair: Arc::new(keypair), keypair: Arc::new(keypair),
dns_resolver: TokioAsyncResolver::tokio_from_system_conf() dns_resolver: TokioAsyncResolver::tokio_from_system_conf()
.map_err(|e| { .map_err(|e| {
error!( t::error!(
"Failed to set up trust dns resolver with system \ "Failed to set up trust dns resolver with system \
config: {}", config: {}",
e e
@ -300,7 +299,12 @@ impl Service {
if !s.supported_room_versions().contains(&s.config.default_room_version) 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 = s.config.default_room_version =
crate::config::default_default_room_version(); crate::config::default_default_room_version();
}; };
@ -356,12 +360,12 @@ impl Service {
self.federation_client.clone() self.federation_client.clone()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn next_count(&self) -> Result<u64> { pub(crate) fn next_count(&self) -> Result<u64> {
self.db.next_count() self.db.next_count()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn current_count(&self) -> Result<u64> { pub(crate) fn current_count(&self) -> Result<u64> {
self.db.current_count() self.db.current_count()
} }
@ -483,7 +487,7 @@ impl Service {
match inner() { match inner() {
Ok(pwd_set) => { Ok(pwd_set) => {
if pwd_set { if pwd_set {
warn!( t::warn!(
"The Grapevine account emergency password is set! \ "The Grapevine account emergency password is set! \
Please unset it as soon as you finish admin account \ Please unset it as soon as you finish admin account \
recovery!" recovery!"
@ -498,7 +502,7 @@ impl Service {
} }
} }
Err(error) => { Err(error) => {
error!( t::error!(
%error, %error,
"Could not set the configured emergency password for the \ "Could not set the configured emergency password for the \
Grapevine user", Grapevine user",

49
src/service/media.rs
View file

@ -9,9 +9,8 @@ use tokio::{
fs::{self, File}, fs::{self, File},
io::{AsyncReadExt, AsyncWriteExt}, io::{AsyncReadExt, AsyncWriteExt},
}; };
use tracing::{debug, warn};
use crate::{services, utils, Error, Result}; use crate::{observability::prelude::*, services, utils, Error, Result};
mod data; mod data;
@ -47,7 +46,7 @@ pub(crate) struct Service {
impl Service { impl Service {
/// Uploads a file. /// Uploads a file.
#[tracing::instrument(skip(self, file))] #[t::instrument(skip(self, file))]
pub(crate) async fn create( pub(crate) async fn create(
&self, &self,
mxc: OwnedMxcUri, mxc: OwnedMxcUri,
@ -68,7 +67,7 @@ impl Service {
} }
/// Uploads or replaces a file thumbnail. /// Uploads or replaces a file thumbnail.
#[tracing::instrument(skip(self, file))] #[t::instrument(skip(self, file))]
pub(crate) async fn upload_thumbnail( pub(crate) async fn upload_thumbnail(
&self, &self,
mxc: OwnedMxcUri, mxc: OwnedMxcUri,
@ -89,7 +88,7 @@ impl Service {
} }
/// Downloads a file. /// Downloads a file.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn get( pub(crate) async fn get(
&self, &self,
mxc: OwnedMxcUri, mxc: OwnedMxcUri,
@ -102,7 +101,7 @@ impl Service {
} }
/// Deletes a media object and all associated thumbnails. /// 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<()> { pub(crate) async fn delete(&self, mxc: OwnedMxcUri) -> Result<()> {
let mut any_files = false; let mut any_files = false;
@ -111,7 +110,7 @@ impl Service {
any_files = true; any_files = true;
self.delete_by_key(thumbnail_key.clone()).await.inspect_err( self.delete_by_key(thumbnail_key.clone()).await.inspect_err(
|error| { |error| {
warn!( t::warn!(
thumbnail_key = utils::u8_slice_to_hex( thumbnail_key = utils::u8_slice_to_hex(
thumbnail_key.as_bytes() thumbnail_key.as_bytes()
), ),
@ -124,12 +123,12 @@ impl Service {
if let Some((_, key)) = if let Some((_, key)) =
self.db.search_file_metadata(mxc, 0, 0).inspect_err( 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; any_files = true;
self.delete_by_key(key).await.inspect_err( 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 { } else {
let error = let error =
Error::BadRequest(ErrorKind::NotFound, "Media not found"); Error::BadRequest(ErrorKind::NotFound, "Media not found");
warn!(%error, "Failed to delete media"); t::warn!(%error, "Failed to delete media");
Err(error) Err(error)
} }
} }
@ -167,7 +166,7 @@ impl Service {
/// ///
/// Each MXC is listed once. Thumbnails are not included separately from the /// Each MXC is listed once. Thumbnails are not included separately from the
/// original media. /// original media.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn iter_all(&self) -> impl Iterator<Item = Result<OwnedMxcUri>> { pub(crate) fn iter_all(&self) -> impl Iterator<Item = Result<OwnedMxcUri>> {
let mut prev_mxc = None; let mut prev_mxc = None;
self.db self.db
@ -206,7 +205,7 @@ impl Service {
/// Generates a thumbnail from the given image file contents. Returns /// Generates a thumbnail from the given image file contents. Returns
/// `Ok(None)` if the input image should be used as-is. /// `Ok(None)` if the input image should be used as-is.
#[tracing::instrument( #[t::instrument(
skip(file), skip(file),
fields(input_size = file.len(), original_width, original_height), fields(input_size = file.len(), original_width, original_height),
)] )]
@ -219,18 +218,18 @@ impl Service {
let image = match image::load_from_memory(file) { let image = match image::load_from_memory(file) {
Ok(image) => image, Ok(image) => image,
Err(error) => { Err(error) => {
warn!(%error, "Failed to parse source image"); t::warn!(%error, "Failed to parse source image");
return Ok(None); return Ok(None);
} }
}; };
let original_width = image.width(); let original_width = image.width();
let original_height = image.height(); let original_height = image.height();
tracing::Span::current().record("original_width", original_width); t::Span::current().record("original_width", original_width);
tracing::Span::current().record("original_height", original_height); t::Span::current().record("original_height", original_height);
if width > original_width || 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); return Ok(None);
} }
@ -276,7 +275,7 @@ impl Service {
image.thumbnail_exact(exact_width, exact_height) image.thumbnail_exact(exact_width, exact_height)
}; };
debug!("Serializing thumbnail as PNG"); t::debug!("Serializing thumbnail as PNG");
let mut thumbnail_bytes = Vec::new(); let mut thumbnail_bytes = Vec::new();
thumbnail.write_to( thumbnail.write_to(
&mut Cursor::new(&mut thumbnail_bytes), &mut Cursor::new(&mut thumbnail_bytes),
@ -299,7 +298,7 @@ impl Service {
/// ///
/// For width,height <= 96 the server uses another thumbnailing algorithm /// For width,height <= 96 the server uses another thumbnailing algorithm
/// which crops the image afterwards. /// which crops the image afterwards.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn get_thumbnail( pub(crate) async fn get_thumbnail(
&self, &self,
mxc: OwnedMxcUri, mxc: OwnedMxcUri,
@ -313,26 +312,26 @@ impl Service {
if let Some((meta, key)) = if let Some((meta, key)) =
self.db.search_file_metadata(mxc.clone(), width, height)? 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))); return Ok(self.read_content(&key).await?.map(|file| (meta, file)));
} }
let Some((meta, key)) = let Some((meta, key)) =
self.db.search_file_metadata(mxc.clone(), 0, 0)? self.db.search_file_metadata(mxc.clone(), 0, 0)?
else { else {
debug!("Original image not found, can't generate thumbnail"); t::debug!("Original image not found, can't generate thumbnail");
return Ok(None); return Ok(None);
}; };
let Some(file) = self.read_content(&key).await? else { 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); return Ok(None);
}; };
debug!("Generating thumbnail"); t::debug!("Generating thumbnail");
let thumbnail_result = { let thumbnail_result = {
let file = file.clone(); let file = file.clone();
let outer_span = tracing::span::Span::current(); let outer_span = t::span::Span::current();
tokio::task::spawn_blocking(move || { tokio::task::spawn_blocking(move || {
outer_span.in_scope(|| { outer_span.in_scope(|| {
@ -344,11 +343,11 @@ impl Service {
}; };
let Some(thumbnail_bytes) = thumbnail_result? else { 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))); 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 // Save thumbnail in database so we don't have to generate it
// again next time // again next time

27
src/service/pdu.rs
View file

@ -22,9 +22,8 @@ use serde_json::{
json, json,
value::{to_raw_value, RawValue as RawJsonValue}, value::{to_raw_value, RawValue as RawJsonValue},
}; };
use tracing::warn;
use crate::Error; use crate::{observability::prelude::*, Error};
/// Content hashes of a PDU. /// Content hashes of a PDU.
#[derive(Clone, Debug, Deserialize, Serialize)] #[derive(Clone, Debug, Deserialize, Serialize)]
@ -60,7 +59,7 @@ pub(crate) struct PduEvent {
} }
impl PduEvent { impl PduEvent {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn redact( pub(crate) fn redact(
&mut self, &mut self,
room_version_id: RoomVersionId, room_version_id: RoomVersionId,
@ -183,7 +182,7 @@ impl PduEvent {
(self.redacts.clone(), self.content.clone()) (self.redacts.clone(), self.content.clone())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn to_sync_room_event(&self) -> Raw<AnySyncTimelineEvent> { pub(crate) fn to_sync_room_event(&self) -> Raw<AnySyncTimelineEvent> {
let (redacts, content) = self.copy_redacts(); let (redacts, content) = self.copy_redacts();
let mut json = json!({ let mut json = json!({
@ -208,7 +207,7 @@ impl PduEvent {
} }
/// This only works for events that are also AnyRoomEvents. /// 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<AnyEphemeralRoomEvent> { pub(crate) fn to_any_event(&self) -> Raw<AnyEphemeralRoomEvent> {
let mut json = json!({ let mut json = json!({
"content": self.content, "content": self.content,
@ -232,7 +231,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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<AnyTimelineEvent> { pub(crate) fn to_room_event(&self) -> Raw<AnyTimelineEvent> {
let (redacts, content) = self.copy_redacts(); let (redacts, content) = self.copy_redacts();
let mut json = json!({ let mut json = json!({
@ -257,7 +256,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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<AnyMessageLikeEvent> { pub(crate) fn to_message_like_event(&self) -> Raw<AnyMessageLikeEvent> {
let (redacts, content) = self.copy_redacts(); let (redacts, content) = self.copy_redacts();
let mut json = json!({ let mut json = json!({
@ -282,7 +281,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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<AnyStateEvent> { pub(crate) fn to_state_event(&self) -> Raw<AnyStateEvent> {
let mut json = json!({ let mut json = json!({
"content": self.content, "content": self.content,
@ -301,7 +300,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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<AnySyncStateEvent> { pub(crate) fn to_sync_state_event(&self) -> Raw<AnySyncStateEvent> {
let mut json = json!({ let mut json = json!({
"content": self.content, "content": self.content,
@ -319,7 +318,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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<AnyStrippedStateEvent> { pub(crate) fn to_stripped_state_event(&self) -> Raw<AnyStrippedStateEvent> {
let json = json!({ let json = json!({
"content": self.content, "content": self.content,
@ -331,7 +330,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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( pub(crate) fn to_stripped_spacechild_state_event(
&self, &self,
) -> Raw<HierarchySpaceChildEvent> { ) -> Raw<HierarchySpaceChildEvent> {
@ -346,7 +345,7 @@ impl PduEvent {
serde_json::from_value(json).expect("Raw::from_value always works") 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( pub(crate) fn to_member_event(
&self, &self,
) -> Raw<StateEvent<RoomMemberEventContent>> { ) -> Raw<StateEvent<RoomMemberEventContent>> {
@ -369,7 +368,7 @@ impl PduEvent {
} }
/// This does not return a full `Pdu` it is only to satisfy ruma's types. /// 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( pub(crate) fn convert_to_outgoing_federation_event(
mut pdu_json: CanonicalJsonObject, mut pdu_json: CanonicalJsonObject,
) -> Box<RawJsonValue> { ) -> Box<RawJsonValue> {
@ -475,7 +474,7 @@ pub(crate) fn gen_event_id_canonical_json(
) -> crate::Result<(OwnedEventId, CanonicalJsonObject)> { ) -> crate::Result<(OwnedEventId, CanonicalJsonObject)> {
let value: CanonicalJsonObject = let value: CanonicalJsonObject =
serde_json::from_str(pdu.get()).map_err(|error| { 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") Error::BadServerResponse("Invalid PDU in server response")
})?; })?;

23
src/service/pusher.rs
View file

@ -23,9 +23,10 @@ use ruma::{
serde::Raw, serde::Raw,
uint, RoomId, UInt, UserId, 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; mod data;
@ -63,7 +64,7 @@ impl Service {
self.db.get_pushkeys(sender) self.db.get_pushkeys(sender)
} }
#[tracing::instrument(skip(self, destination, request))] #[t::instrument(skip(self, destination, request))]
pub(crate) async fn send_request<T>( pub(crate) async fn send_request<T>(
&self, &self,
destination: &str, destination: &str,
@ -81,7 +82,7 @@ impl Service {
&[MatrixVersion::V1_0], &[MatrixVersion::V1_0],
) )
.map_err(|error| { .map_err(|error| {
warn!(%error, %destination, "Failed to find destination"); t::warn!(%error, %destination, "Failed to find destination");
Error::BadServerResponse("Invalid destination") Error::BadServerResponse("Invalid destination")
})? })?
.map(BytesMut::freeze); .map(BytesMut::freeze);
@ -108,12 +109,12 @@ impl Service {
// TODO: handle timeout // TODO: handle timeout
let body = response.bytes().await.unwrap_or_else(|error| { let body = response.bytes().await.unwrap_or_else(|error| {
warn!(%error, "Server error"); t::warn!(%error, "Server error");
Vec::new().into() Vec::new().into()
}); });
if status != 200 { if status != 200 {
warn!( t::warn!(
push_gateway = %destination, push_gateway = %destination,
%status, %status,
%url, %url,
@ -131,7 +132,7 @@ impl Service {
.expect("reqwest body is valid http body"), .expect("reqwest body is valid http body"),
); );
response.map_err(|error| { response.map_err(|error| {
warn!( t::warn!(
%error, %error,
appservice = %destination, appservice = %destination,
%url, %url,
@ -143,7 +144,7 @@ impl Service {
}) })
} }
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
%destination, %destination,
"Could not send request to push gateway", "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( pub(crate) async fn send_push_notice(
&self, &self,
user: &UserId, user: &UserId,
@ -210,7 +211,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, user, ruleset, pdu))] #[t::instrument(skip(self, user, ruleset, pdu))]
pub(crate) fn get_actions<'a>( pub(crate) fn get_actions<'a>(
&self, &self,
user: &UserId, user: &UserId,
@ -240,7 +241,7 @@ impl Service {
Ok(ruleset.get_actions(pdu, &ctx)) 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( async fn send_notice(
&self, &self,
unread: UInt, unread: UInt,

25
src/service/rooms/auth_chain.rs
View file

@ -5,11 +5,10 @@ use std::{
use lru_cache::LruCache; use lru_cache::LruCache;
use ruma::{api::client::error::ErrorKind, EventId, RoomId}; use ruma::{api::client::error::ErrorKind, EventId, RoomId};
use tracing::{debug, error, warn};
use super::short::ShortEventId; use super::short::ShortEventId;
use crate::{ use crate::{
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
services, services,
utils::debug_slice_truncated, utils::debug_slice_truncated,
Error, Result, Error, Result,
@ -66,7 +65,7 @@ impl Service {
Ok(Some(chain)) Ok(Some(chain))
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn cache_auth_chain( pub(crate) fn cache_auth_chain(
&self, &self,
key: Vec<ShortEventId>, key: Vec<ShortEventId>,
@ -79,7 +78,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument( #[t::instrument(
skip(self, starting_events), skip(self, starting_events),
fields(starting_events = debug_slice_truncated(&starting_events, 5)), fields(starting_events = debug_slice_truncated(&starting_events, 5)),
)] )]
@ -146,7 +145,7 @@ impl Service {
vec![sevent_id], vec![sevent_id],
Arc::clone(&auth_chain), Arc::clone(&auth_chain),
)?; )?;
debug!( t::debug!(
event_id = ?event_id, event_id = ?event_id,
chain_length = ?auth_chain.len(), chain_length = ?auth_chain.len(),
"Cache missed event" "Cache missed event"
@ -159,7 +158,7 @@ impl Service {
} }
}; };
} }
debug!( t::debug!(
chunk_cache_length = ?chunk_cache.len(), chunk_cache_length = ?chunk_cache.len(),
hits = ?hits2, hits = ?hits2,
misses = ?misses2, misses = ?misses2,
@ -170,7 +169,7 @@ impl Service {
full_auth_chain.extend(chunk_cache.iter()); full_auth_chain.extend(chunk_cache.iter());
} }
debug!( t::debug!(
chain_length = ?full_auth_chain.len(), chain_length = ?full_auth_chain.len(),
hits = ?hits, hits = ?hits,
misses = ?misses, misses = ?misses,
@ -182,7 +181,7 @@ impl Service {
})) }))
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn get_auth_chain_inner( fn get_auth_chain_inner(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -195,7 +194,11 @@ impl Service {
match services().rooms.timeline.get_pdu(&event_id) { match services().rooms.timeline.get_pdu(&event_id) {
Ok(Some(pdu)) => { Ok(Some(pdu)) => {
if pdu.room_id != room_id { 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( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Event has incorrect room id", "Event has incorrect room id",
@ -214,13 +217,13 @@ impl Service {
} }
} }
Ok(None) => { Ok(None) => {
warn!( t::warn!(
?event_id, ?event_id,
"Could not find pdu mentioned in auth events" "Could not find pdu mentioned in auth events"
); );
} }
Err(error) => { Err(error) => {
error!( t::error!(
?event_id, ?event_id,
?error, ?error,
"Could not load event in auth chain" "Could not load event in auth chain"

21
src/service/rooms/edus/typing.rs
View file

@ -5,9 +5,8 @@ use ruma::{
OwnedRoomId, OwnedUserId, RoomId, UserId, OwnedRoomId, OwnedUserId, RoomId, UserId,
}; };
use tokio::sync::{broadcast, RwLock}; use tokio::sync::{broadcast, RwLock};
use tracing::trace;
use crate::{services, utils, Result}; use crate::{observability::prelude::*, services, utils, Result};
pub(crate) struct Service { pub(crate) struct Service {
// u64 is unix timestamp of timeout // u64 is unix timestamp of timeout
@ -28,7 +27,7 @@ impl Service {
/// Sets a user as typing until the timeout timestamp is reached or /// Sets a user as typing until the timeout timestamp is reached or
/// `roomtyping_remove` is called. /// `roomtyping_remove` is called.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn typing_add( pub(crate) async fn typing_add(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -46,7 +45,7 @@ impl Service {
.await .await
.insert(room_id.to_owned(), services().globals.next_count()?); .insert(room_id.to_owned(), services().globals.next_count()?);
if self.typing_update_sender.send(room_id.to_owned()).is_err() { 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 \ "receiver found what it was looking for and is no longer \
interested" interested"
); );
@ -55,7 +54,7 @@ impl Service {
} }
/// Removes a user from typing before the timeout is reached. /// Removes a user from typing before the timeout is reached.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn typing_remove( pub(crate) async fn typing_remove(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -72,7 +71,7 @@ impl Service {
.await .await
.insert(room_id.to_owned(), services().globals.next_count()?); .insert(room_id.to_owned(), services().globals.next_count()?);
if self.typing_update_sender.send(room_id.to_owned()).is_err() { 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 \ "receiver found what it was looking for and is no longer \
interested" interested"
); );
@ -80,7 +79,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn wait_for_update(&self, room_id: &RoomId) -> Result<()> { pub(crate) async fn wait_for_update(&self, room_id: &RoomId) -> Result<()> {
let mut receiver = self.typing_update_sender.subscribe(); let mut receiver = self.typing_update_sender.subscribe();
while let Ok(next) = receiver.recv().await { while let Ok(next) = receiver.recv().await {
@ -93,7 +92,7 @@ impl Service {
} }
/// Makes sure that typing events with old timestamps get removed. /// 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<()> { async fn typings_maintain(&self, room_id: &RoomId) -> Result<()> {
let current_timestamp = utils::millis_since_unix_epoch(); let current_timestamp = utils::millis_since_unix_epoch();
let mut removable = Vec::new(); let mut removable = Vec::new();
@ -120,7 +119,7 @@ impl Service {
.await .await
.insert(room_id.to_owned(), services().globals.next_count()?); .insert(room_id.to_owned(), services().globals.next_count()?);
if self.typing_update_sender.send(room_id.to_owned()).is_err() { 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 \ "receiver found what it was looking for and is no longer \
interested" interested"
); );
@ -130,7 +129,7 @@ impl Service {
} }
/// Returns the count of the last typing update in this room. /// 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( pub(crate) async fn last_typing_update(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -146,7 +145,7 @@ impl Service {
} }
/// Returns a new typing EDU. /// Returns a new typing EDU.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn typings_all( pub(crate) async fn typings_all(
&self, &self,
room_id: &RoomId, room_id: &RoomId,

197
src/service/rooms/event_handler.rs
View file

@ -34,13 +34,13 @@ use ruma::{
use serde::Deserialize; use serde::Deserialize;
use serde_json::value::RawValue as RawJsonValue; use serde_json::value::RawValue as RawJsonValue;
use tokio::sync::{RwLock, RwLockWriteGuard, Semaphore}; use tokio::sync::{RwLock, RwLockWriteGuard, Semaphore};
use tracing::{debug, error, info, trace, warn};
use super::{ use super::{
short::ShortStateKey, state_compressor::CompressedStateEvent, short::ShortStateKey, state_compressor::CompressedStateEvent,
timeline::PduId, timeline::PduId,
}; };
use crate::{ use crate::{
observability::prelude::*,
service::{globals::SigningKeys, pdu, rooms::state::ExtractVersion}, service::{globals::SigningKeys, pdu, rooms::state::ExtractVersion},
services, services,
utils::{debug_slice_truncated, room_version::RoomVersion}, utils::{debug_slice_truncated, room_version::RoomVersion},
@ -82,7 +82,7 @@ impl Service {
/// 13. Use state resolution to find new room state /// 13. Use state resolution to find new room state
/// 14. Check if the event passes auth based on the "current state" of the /// 14. Check if the event passes auth based on the "current state" of the
/// room, if not soft fail it /// 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>( pub(crate) async fn handle_incoming_pdu<'a>(
&self, &self,
origin: &'a ServerName, origin: &'a ServerName,
@ -160,7 +160,7 @@ impl Service {
.await?; .await?;
let mut errors = 0; 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 { for prev_id in sorted_prev_events {
// Check for disabled again because it might have changed // Check for disabled again because it might have changed
if services().rooms.metadata.is_disabled(room_id)? { if services().rooms.metadata.is_disabled(room_id)? {
@ -186,7 +186,10 @@ impl Service {
} }
if time.elapsed() < min_elapsed_duration { 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; continue;
} }
} }
@ -239,7 +242,7 @@ impl Service {
.await .await
{ {
errors += 1; errors += 1;
warn!(%error, event_id = %prev_id, "Prev event failed"); t::warn!(%error, event_id = %prev_id, "Prev event failed");
match services() match services()
.globals .globals
.bad_event_ratelimiter .bad_event_ratelimiter
@ -261,7 +264,7 @@ impl Service {
.write() .write()
.await .await
.remove(&room_id.to_owned()); .remove(&room_id.to_owned());
debug!( t::debug!(
elapsed = ?start_time.elapsed(), elapsed = ?start_time.elapsed(),
event_id = %prev_id, event_id = %prev_id,
"Finished handling prev event", "Finished handling prev event",
@ -299,7 +302,7 @@ impl Service {
} }
#[allow(clippy::too_many_arguments)] #[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>( fn handle_outlier_pdu<'a>(
&'a self, &'a self,
origin: &'a ServerName, origin: &'a ServerName,
@ -333,7 +336,7 @@ impl Service {
let origin_server_ts = let origin_server_ts =
value.get("origin_server_ts").ok_or_else(|| { 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( Error::BadRequest(
ErrorKind::MissingParam, ErrorKind::MissingParam,
"Invalid PDU, no origin_server_ts field", "Invalid PDU, no origin_server_ts field",
@ -377,7 +380,7 @@ impl Service {
) { ) {
Err(error) => { Err(error) => {
// Drop // Drop
warn!(%event_id, %error, "Dropping bad event"); t::warn!(%event_id, %error, "Dropping bad event");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::InvalidParam, ErrorKind::InvalidParam,
"Signature verification failed", "Signature verification failed",
@ -385,7 +388,7 @@ impl Service {
} }
Ok(ruma::signatures::Verified::Signatures) => { Ok(ruma::signatures::Verified::Signatures) => {
// Redact // 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( let Ok(obj) = ruma::canonical_json::redact(
value, value,
room_version_id, room_version_id,
@ -440,7 +443,10 @@ impl Service {
// to auth events" // to auth events"
// NOTE: Step 5 is not applied anymore because it failed too // NOTE: Step 5 is not applied anymore because it failed too
// often // 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( self.fetch_and_handle_outliers(
origin, origin,
&incoming_pdu &incoming_pdu
@ -457,7 +463,7 @@ impl Service {
// 6. Reject "due to auth events" if the event doesn't pass auth // 6. Reject "due to auth events" if the event doesn't pass auth
// based on the auth events // based on the auth events
debug!( t::debug!(
event_id = %incoming_pdu.event_id, event_id = %incoming_pdu.event_id,
"Starting auth check for event based on auth events", "Starting auth check for event based on auth events",
); );
@ -468,7 +474,7 @@ impl Service {
let Some(auth_event) = let Some(auth_event) =
services().rooms.timeline.get_pdu(event_id)? services().rooms.timeline.get_pdu(event_id)?
else { else {
warn!(%event_id, "Could not find auth event"); t::warn!(%event_id, "Could not find auth event");
continue; continue;
}; };
@ -521,7 +527,7 @@ impl Service {
)); ));
} }
debug!("Validation successful"); t::debug!("Validation successful");
// 7. Persist the event as an outlier. // 7. Persist the event as an outlier.
services() services()
@ -529,13 +535,13 @@ impl Service {
.outlier .outlier
.add_pdu_outlier(&incoming_pdu.event_id, &val)?; .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)) Ok((Arc::new(incoming_pdu), val))
}) })
} }
#[tracing::instrument(skip_all, fields( #[t::instrument(skip_all, fields(
incoming_pdu = %incoming_pdu.event_id, incoming_pdu = %incoming_pdu.event_id,
))] ))]
pub(crate) async fn upgrade_outlier_to_timeline_pdu( pub(crate) async fn upgrade_outlier_to_timeline_pdu(
@ -565,7 +571,7 @@ impl Service {
)); ));
} }
debug!( t::debug!(
event_id = %incoming_pdu.event_id, event_id = %incoming_pdu.event_id,
"Upgrading event to timeline pdu", "Upgrading event to timeline pdu",
); );
@ -584,7 +590,7 @@ impl Service {
// the request and build the state from a known point and // the request and build the state from a known point and
// resolve if > 1 prev_event // resolve if > 1 prev_event
debug!("Requesting state at event"); t::debug!("Requesting state at event");
let mut state_at_incoming_event = None; let mut state_at_incoming_event = None;
if incoming_pdu.prev_events.len() == 1 { if incoming_pdu.prev_events.len() == 1 {
@ -607,7 +613,7 @@ impl Service {
}; };
if let Some(Ok(mut state)) = state { if let Some(Ok(mut state)) = state {
debug!("Using cached state"); t::debug!("Using cached state");
let prev_pdu = services() let prev_pdu = services()
.rooms .rooms
.timeline .timeline
@ -634,7 +640,7 @@ impl Service {
state_at_incoming_event = Some(state); state_at_incoming_event = Some(state);
} }
} else { } 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 extremity_sstatehashes = HashMap::new();
let mut okay = true; let mut okay = true;
@ -701,7 +707,7 @@ impl Service {
id.clone(), id.clone(),
); );
} else { } else {
warn!("Failed to get_statekey_from_short"); t::warn!("Failed to get_statekey_from_short");
} }
starting_events.push(id); starting_events.push(id);
} }
@ -727,7 +733,10 @@ impl Service {
|event_id| { |event_id| {
let res = services().rooms.timeline.get_pdu(event_id); let res = services().rooms.timeline.get_pdu(event_id);
if let Err(error) = &res { 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() res.ok().flatten()
}, },
@ -751,7 +760,7 @@ impl Service {
.collect::<Result<_>>()?, .collect::<Result<_>>()?,
), ),
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
"State resolution on prev events failed, either \ "State resolution on prev events failed, either \
an event could not be found or deserialization" an event could not be found or deserialization"
@ -763,7 +772,7 @@ impl Service {
} }
if state_at_incoming_event.is_none() { 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 // Call /state_ids to find out what the state at this pdu is. We
// trust the server's response to some extend, but we // trust the server's response to some extend, but we
// still do a lot of checks on the events // still do a lot of checks on the events
@ -779,7 +788,7 @@ impl Service {
.await .await
{ {
Ok(res) => { Ok(res) => {
debug!("Fetching state events at event"); t::debug!("Fetching state events at event");
let collect = res let collect = res
.pdu_ids .pdu_ids
.iter() .iter()
@ -863,7 +872,7 @@ impl Service {
state_at_incoming_event = Some(state); state_at_incoming_event = Some(state);
} }
Err(error) => { Err(error) => {
warn!(%error, "Fetching state for event failed"); t::warn!(%error, "Fetching state for event failed");
return Err(error); return Err(error);
} }
}; };
@ -872,7 +881,7 @@ impl Service {
let state_at_incoming_event = let state_at_incoming_event =
state_at_incoming_event.expect("we always set this to some above"); 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 // 11. Check the auth of the event passes based on the state of the
// event // event
let check_result = state_res::event_auth::auth_check( 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.", "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 // Soft fail check before doing state res
let auth_events = services().rooms.state.get_auth_events( 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 // Now we calculate the set of extremities this room has after the
// incoming event has been applied. We start with the previous // incoming event has been applied. We start with the previous
// extremities (aka leaves) // extremities (aka leaves)
debug!("Calculating extremities"); t::debug!("Calculating extremities");
let mut extremities = let mut extremities =
services().rooms.state.get_forward_extremities(room_id)?; 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( let state_ids_compressed = Arc::new(
state_at_incoming_event state_at_incoming_event
.iter() .iter()
@ -1006,7 +1015,7 @@ impl Service {
); );
if incoming_pdu.state_key.is_some() { 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 // We also add state after incoming event to the fork states
let mut state_after = state_at_incoming_event.clone(); let mut state_after = state_at_incoming_event.clone();
@ -1026,7 +1035,7 @@ impl Service {
.await?; .await?;
// Set the new room state to the resolved state // 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() let (sstatehash, new, removed) = services()
.rooms .rooms
@ -1042,7 +1051,7 @@ impl Service {
// 14. Check if the event passes auth based on the "current state" of // 14. Check if the event passes auth based on the "current state" of
// the room, if not soft fail it // the room, if not soft fail it
debug!("Starting soft fail auth check"); t::debug!("Starting soft fail auth check");
if soft_fail { if soft_fail {
services() services()
@ -1060,7 +1069,7 @@ impl Service {
// Soft fail, we keep the event as an outlier but don't add it to // Soft fail, we keep the event as an outlier but don't add it to
// the timeline // the timeline
warn!("Event was soft failed"); t::warn!("Event was soft failed");
services() services()
.rooms .rooms
.pdu_metadata .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()); extremities.insert(incoming_pdu.event_id.clone());
// Now that the event has passed all auth it is added into the timeline. // Now that the event has passed all auth it is added into the timeline.
@ -1091,21 +1100,21 @@ impl Service {
) )
.await?; .await?;
debug!("Appended incoming pdu"); t::debug!("Appended incoming pdu");
// Event has passed all auth/stateres checks // Event has passed all auth/stateres checks
drop(room_token); drop(room_token);
Ok(pdu_id) 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( async fn resolve_state(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
room_version_id: &RoomVersionId, room_version_id: &RoomVersionId,
incoming_state: HashMap<ShortStateKey, Arc<EventId>>, incoming_state: HashMap<ShortStateKey, Arc<EventId>>,
) -> Result<Arc<HashSet<CompressedStateEvent>>> { ) -> Result<Arc<HashSet<CompressedStateEvent>>> {
debug!("Loading current room state ids"); t::debug!("Loading current room state ids");
let current_sstatehash = services() let current_sstatehash = services()
.rooms .rooms
.state .state
@ -1135,7 +1144,7 @@ impl Service {
); );
} }
debug!("Loading fork states"); t::debug!("Loading fork states");
let fork_states: Vec<_> = fork_states let fork_states: Vec<_> = fork_states
.into_iter() .into_iter()
@ -1155,12 +1164,12 @@ impl Service {
}) })
.collect(); .collect();
debug!("Resolving state"); t::debug!("Resolving state");
let fetch_event = |id: &_| { let fetch_event = |id: &_| {
let res = services().rooms.timeline.get_pdu(id); let res = services().rooms.timeline.get_pdu(id);
if let Err(error) = &res { if let Err(error) = &res {
error!(%error, "Failed to fetch event"); t::error!(%error, "Failed to fetch event");
} }
res.ok().flatten() res.ok().flatten()
}; };
@ -1180,7 +1189,7 @@ impl Service {
drop(lock); drop(lock);
debug!("State resolution done; compressing state"); t::debug!("State resolution done; compressing state");
let new_room_state = state let new_room_state = state
.into_iter() .into_iter()
@ -1209,7 +1218,7 @@ impl Service {
/// b. Look at outlier pdu tree /// b. Look at outlier pdu tree
/// c. Ask origin server over federation /// c. Ask origin server over federation
/// d. TODO: Ask other servers 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>( pub(crate) fn fetch_and_handle_outliers<'a>(
&'a self, &'a self,
origin: &'a ServerName, origin: &'a ServerName,
@ -1244,7 +1253,7 @@ impl Service {
if let Ok(Some(local_pdu)) = if let Ok(Some(local_pdu)) =
services().rooms.timeline.get_pdu(event_id) 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)); pdus.push((local_pdu, None));
continue; continue;
} }
@ -1275,7 +1284,7 @@ impl Service {
} }
if time.elapsed() < min_elapsed_duration { if time.elapsed() < min_elapsed_duration {
info!( t::info!(
event_id = %next_id, event_id = %next_id,
"Backing off from event", "Backing off from event",
); );
@ -1295,11 +1304,11 @@ impl Service {
if let Ok(Some(_)) = if let Ok(Some(_)) =
services().rooms.timeline.get_pdu(&next_id) 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; continue;
} }
info!( t::info!(
event_id = %next_id, event_id = %next_id,
"Fetching event over federation", "Fetching event over federation",
); );
@ -1313,7 +1322,10 @@ impl Service {
) )
.await .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)) = let Ok((calculated_event_id, value)) =
pdu::gen_event_id_canonical_json( pdu::gen_event_id_canonical_json(
&res.pdu, &res.pdu,
@ -1325,7 +1337,7 @@ impl Service {
}; };
if calculated_event_id != *next_id { if calculated_event_id != *next_id {
warn!( t::warn!(
expected_event_id = %next_id, expected_event_id = %next_id,
actual_event_id = %calculated_event_id, actual_event_id = %calculated_event_id,
"Server returned an event with a different ID \ "Server returned an event with a different ID \
@ -1343,17 +1355,17 @@ impl Service {
let a: Arc<EventId> = auth_event; let a: Arc<EventId> = auth_event;
todo_auth_events.push(a); todo_auth_events.push(a);
} else { } else {
warn!("Auth event id is not valid"); t::warn!("Auth event id is not valid");
} }
} }
} else { } else {
warn!("Auth event list invalid"); t::warn!("Auth event list invalid");
} }
events_in_reverse_order.push((next_id.clone(), value)); events_in_reverse_order.push((next_id.clone(), value));
events_all.insert(next_id); events_all.insert(next_id);
} else { } 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; back_off((*next_id).to_owned()).await;
} }
} }
@ -1377,7 +1389,7 @@ impl Service {
} }
if time.elapsed() < min_elapsed_duration { if time.elapsed() < min_elapsed_duration {
info!( t::info!(
event_id = %next_id, event_id = %next_id,
"Backing off from event", "Backing off from event",
); );
@ -1403,7 +1415,7 @@ impl Service {
} }
} }
Err(error) => { Err(error) => {
warn!( t::warn!(
event_id = %next_id, event_id = %next_id,
%error, %error,
"Event failed auth checks", "Event failed auth checks",
@ -1417,7 +1429,7 @@ impl Service {
}) })
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
async fn fetch_unknown_prev_events( async fn fetch_unknown_prev_events(
&self, &self,
@ -1457,7 +1469,7 @@ impl Service {
if amount > services().globals.max_fetch_prev_events() { if amount > services().globals.max_fetch_prev_events() {
// Max limit reached // Max limit reached
warn!("Max prev event limit reached!"); t::warn!("Max prev event limit reached!");
graph.insert(prev_event_id.clone(), HashSet::new()); graph.insert(prev_event_id.clone(), HashSet::new());
continue; continue;
} }
@ -1519,7 +1531,7 @@ impl Service {
Ok((sorted, eventid_info)) Ok((sorted, eventid_info))
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
pub(crate) async fn fetch_required_signing_keys( pub(crate) async fn fetch_required_signing_keys(
&self, &self,
event: &CanonicalJsonObject, event: &CanonicalJsonObject,
@ -1560,7 +1572,7 @@ impl Service {
.await; .await;
let Ok(keys) = fetch_res else { let Ok(keys) = fetch_res else {
warn!("Failed to fetch signing key"); t::warn!("Failed to fetch signing key");
continue; continue;
}; };
@ -1573,7 +1585,7 @@ impl Service {
// Gets a list of servers for which we don't have the signing key yet. We go // 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 // over the PDUs and either cache the key or add it to the list that
// needs to be retrieved. // needs to be retrieved.
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn get_server_keys_from_cache( async fn get_server_keys_from_cache(
&self, &self,
pdu: &RawJsonValue, pdu: &RawJsonValue,
@ -1586,7 +1598,7 @@ impl Service {
) -> Result<()> { ) -> Result<()> {
let value: CanonicalJsonObject = serde_json::from_str(pdu.get()) let value: CanonicalJsonObject = serde_json::from_str(pdu.get())
.map_err(|error| { .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") Error::BadServerResponse("Invalid PDU in server response")
})?; })?;
@ -1618,7 +1630,7 @@ impl Service {
} }
if time.elapsed() < min_elapsed_duration { 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( return Err(Error::BadServerResponse(
"Bad event, still backing off", "Bad event, still backing off",
)); ));
@ -1674,11 +1686,14 @@ impl Service {
continue; 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)?; let result = services().globals.signing_keys_for(origin)?;
if !result.as_ref().is_some_and(contains_all_ids) { if !result.as_ref().is_some_and(contains_all_ids) {
trace!( t::trace!(
server = %origin, server = %origin,
"Signing key not loaded for server", "Signing key not loaded for server",
); );
@ -1724,7 +1739,7 @@ impl Service {
) )
.await .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() { if servers.is_empty() {
info!("We had all keys locally"); t::info!("We had all keys locally");
return Ok(()); return Ok(());
} }
for server in services().globals.trusted_servers() { 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() if let Ok(keys) = services()
.sending .sending
.send_federation_request( .send_federation_request(
@ -1748,13 +1763,13 @@ impl Service {
) )
.await .await
{ {
trace!(signing_keys = ?keys, "Got signing keys"); t::trace!(signing_keys = ?keys, "Got signing keys");
let mut pkm = pub_key_map.write().await; let mut pkm = pub_key_map.write().await;
for k in keys.server_keys { for k in keys.server_keys {
let k = match k.deserialize() { let k = match k.deserialize() {
Ok(key) => key, Ok(key) => key,
Err(error) => { Err(error) => {
warn!( t::warn!(
%error, %error,
%server, %server,
object = ?k.json(), object = ?k.json(),
@ -1779,12 +1794,12 @@ impl Service {
} }
if servers.is_empty() { if servers.is_empty() {
info!("Trusted server supplied all signing keys"); t::info!("Trusted server supplied all signing keys");
return Ok(()); return Ok(());
} }
} }
info!(?servers, "Asking individual servers for signing keys"); t::info!(?servers, "Asking individual servers for signing keys");
let mut futures: FuturesUnordered<_> = servers let mut futures: FuturesUnordered<_> = servers
.into_keys() .into_keys()
.map(|server| async move { .map(|server| async move {
@ -1803,7 +1818,7 @@ impl Service {
while let Some(result) = futures.next().await { while let Some(result) = futures.next().await {
if let (Ok(get_keys_response), origin) = result { 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() { if let Ok(key) = get_keys_response.server_key.deserialize() {
let result = services() let result = services()
.globals .globals
@ -1814,10 +1829,10 @@ impl Service {
.insert(origin.to_string(), result); .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(()) Ok(())
} }
@ -1825,7 +1840,7 @@ impl Service {
/// Returns Ok if the acl allows the server /// Returns Ok if the acl allows the server
// Allowed because this function uses `services()` // Allowed because this function uses `services()`
#[allow(clippy::unused_self)] #[allow(clippy::unused_self)]
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
pub(crate) fn acl_check( pub(crate) fn acl_check(
&self, &self,
server_name: &ServerName, server_name: &ServerName,
@ -1846,7 +1861,7 @@ impl Service {
{ {
Ok(x) => x, Ok(x) => x,
Err(error) => { Err(error) => {
warn!(%error, "Invalid ACL event"); t::warn!(%error, "Invalid ACL event");
return Ok(()); return Ok(());
} }
}; };
@ -1859,7 +1874,7 @@ impl Service {
if acl_event_content.is_allowed(server_name) { if acl_event_content.is_allowed(server_name) {
Ok(()) Ok(())
} else { } else {
info!( t::info!(
server = %server_name, server = %server_name,
%room_id, %room_id,
"Other server was denied by room ACL", "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 /// 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. /// them fetch them from the server and save to our DB.
#[tracing::instrument( #[t::instrument(
skip(self, signature_ids), skip(self, signature_ids),
fields(signature_ids = debug_slice_truncated(&signature_ids, 3)) fields(signature_ids = debug_slice_truncated(&signature_ids, 3))
)] )]
@ -1899,7 +1914,7 @@ impl Service {
.any(|key_id| id == &key_id); .any(|key_id| id == &key_id);
if !in_verify_keys && !in_old_verify_keys { 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; return false;
} }
} }
@ -1945,14 +1960,14 @@ impl Service {
} }
if time.elapsed() < min_elapsed_duration { 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( return Err(Error::BadServerResponse(
"bad signature, still backing off", "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)?; let result = services().globals.signing_keys_for(origin)?;
@ -1964,7 +1979,7 @@ impl Service {
) )
.expect("Should be valid until year 500,000,000"); .expect("Should be valid until year 500,000,000");
debug!( t::debug!(
server = %origin, server = %origin,
key_ids = ?result.verify_keys.keys().collect::<Vec<_>>(), key_ids = ?result.verify_keys.keys().collect::<Vec<_>>(),
old_key_ids = old_key_ids =
@ -1978,7 +1993,7 @@ impl Service {
// We want to ensure that the keys remain valid by the time the // We want to ensure that the keys remain valid by the time the
// other functions that handle signatures reach them // other functions that handle signatures reach them
if result.valid_until_ts > ts_threshold { if result.valid_until_ts > ts_threshold {
debug!( t::debug!(
origin = %origin, origin = %origin,
valid_until_ts = %result.valid_until_ts.get(), valid_until_ts = %result.valid_until_ts.get(),
"Keys are valid because they expire after threshold", "Keys are valid because they expire after threshold",
@ -1987,7 +2002,7 @@ impl Service {
} }
expires_soon_or_has_expired = true; 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"); .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() if let Some(mut server_key) = services()
.sending .sending
@ -2052,7 +2067,7 @@ impl Service {
if query_via_trusted_servers { if query_via_trusted_servers {
for server in services().globals.trusted_servers() { for server in services().globals.trusted_servers() {
debug!( t::debug!(
trusted_server = %server, trusted_server = %server,
origin = %origin, origin = %origin,
"Asking trusted server for signing keys", "Asking trusted server for signing keys",
@ -2080,7 +2095,7 @@ impl Service {
.collect::<Vec<_>>() .collect::<Vec<_>>()
}) })
{ {
trace!( t::trace!(
?server_keys, ?server_keys,
"Got signing keys from trusted server" "Got signing keys from trusted server"
); );
@ -2129,7 +2144,7 @@ impl Service {
.map(|(id, key)| (id.to_string(), key)), .map(|(id, key)| (id.to_string(), key)),
); );
} else { } else {
warn!( t::warn!(
origin = %origin, origin = %origin,
valid_until = %k.valid_until_ts.get(), valid_until = %k.valid_until_ts.get(),
"Server gave us keys older than we \ "Server gave us keys older than we \
@ -2147,7 +2162,7 @@ impl Service {
// We should return these keys if fresher keys were not found // We should return these keys if fresher keys were not found
if expires_soon_or_has_expired { if expires_soon_or_has_expired {
info!(origin = %origin, "Returning stale keys"); t::info!(origin = %origin, "Returning stale keys");
return Ok(keys); return Ok(keys);
} }
@ -2155,14 +2170,14 @@ impl Service {
back_off(signature_ids).await; 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")) 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<()> { fn check_room_id(room_id: &RoomId, pdu: &PduEvent) -> Result<()> {
if pdu.room_id != room_id { if pdu.room_id != room_id {
warn!( t::warn!(
event_id = %pdu.event_id, event_id = %pdu.event_id,
expected_room_id = %pdu.room_id, expected_room_id = %pdu.room_id,
actual_room_id = %room_id, actual_room_id = %room_id,

10
src/service/rooms/lazy_loading.rs
View file

@ -4,7 +4,7 @@ use ruma::{DeviceId, OwnedDeviceId, OwnedRoomId, OwnedUserId, RoomId, UserId};
use tokio::sync::Mutex; use tokio::sync::Mutex;
use super::timeline::PduCount; use super::timeline::PduCount;
use crate::Result; use crate::{observability::prelude::*, Result};
mod data; mod data;
@ -30,7 +30,7 @@ impl Service {
} }
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn lazy_load_was_sent_before( pub(crate) fn lazy_load_was_sent_before(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -41,7 +41,7 @@ impl Service {
self.db.lazy_load_was_sent_before(user_id, device_id, room_id, ll_user) 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( pub(crate) async fn lazy_load_mark_sent(
&self, &self,
user_id: &UserId, 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( pub(crate) async fn lazy_load_confirm_delivery(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -86,7 +86,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn lazy_load_reset( pub(crate) fn lazy_load_reset(
&self, &self,
user_id: &UserId, user_id: &UserId,

16
src/service/rooms/pdu_metadata.rs
View file

@ -8,7 +8,7 @@ use ruma::{
use serde::Deserialize; use serde::Deserialize;
use super::timeline::PduCount; use super::timeline::PduCount;
use crate::{services, PduEvent, Result}; use crate::{observability::prelude::*, services, PduEvent, Result};
mod data; mod data;
@ -29,7 +29,7 @@ struct ExtractRelatesToEventId {
} }
impl Service { impl Service {
#[tracing::instrument(skip(self, from, to))] #[t::instrument(skip(self, from, to))]
pub(crate) fn add_relation( pub(crate) fn add_relation(
&self, &self,
from: PduCount, from: PduCount,
@ -48,7 +48,7 @@ impl Service {
} }
#[allow(clippy::too_many_arguments, clippy::too_many_lines)] #[allow(clippy::too_many_arguments, clippy::too_many_lines)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn paginate_relations_with_filter( pub(crate) fn paginate_relations_with_filter(
&self, &self,
sender_user: &UserId, sender_user: &UserId,
@ -176,7 +176,7 @@ impl Service {
} }
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
pub(crate) fn relations_until<'a>( pub(crate) fn relations_until<'a>(
&'a self, &'a self,
user_id: &'a UserId, user_id: &'a UserId,
@ -195,7 +195,7 @@ impl Service {
self.db.relations_until(user_id, room_id, target, until) 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( pub(crate) fn mark_as_referenced(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -204,7 +204,7 @@ impl Service {
self.db.mark_as_referenced(room_id, event_ids) self.db.mark_as_referenced(room_id, event_ids)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn is_event_referenced( pub(crate) fn is_event_referenced(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -213,7 +213,7 @@ impl Service {
self.db.is_event_referenced(room_id, event_id) self.db.is_event_referenced(room_id, event_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn mark_event_soft_failed( pub(crate) fn mark_event_soft_failed(
&self, &self,
event_id: &EventId, event_id: &EventId,
@ -221,7 +221,7 @@ impl Service {
self.db.mark_event_soft_failed(event_id) self.db.mark_event_soft_failed(event_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn is_event_soft_failed( pub(crate) fn is_event_soft_failed(
&self, &self,
event_id: &EventId, event_id: &EventId,

31
src/service/rooms/spaces.rs
View file

@ -29,10 +29,9 @@ use ruma::{
OwnedRoomId, RoomId, UserId, OwnedRoomId, RoomId, UserId,
}; };
use tokio::sync::Mutex; use tokio::sync::Mutex;
use tracing::{debug, error, warn};
use super::state::ExtractType; use super::state::ExtractType;
use crate::{services, Error, PduEvent, Result}; use crate::{observability::prelude::*, services, Error, PduEvent, Result};
pub(crate) enum CachedJoinRule { pub(crate) enum CachedJoinRule {
Full(JoinRule), Full(JoinRule),
@ -59,7 +58,7 @@ impl Service {
} }
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn get_hierarchy( pub(crate) async fn get_hierarchy(
&self, &self,
sender_user: &UserId, sender_user: &UserId,
@ -185,7 +184,7 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomJoinRulesEventContent| c.join_rule) .map(|c: RoomJoinRulesEventContent| c.join_rule)
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
"Invalid room join rule event" "Invalid room join rule event"
); );
@ -224,7 +223,7 @@ impl Service {
// Early return so the client can see some data already // Early return so the client can see some data already
break; break;
} }
debug!(%server, "Asking other server for /hierarchy"); t::debug!(%server, "Asking other server for /hierarchy");
if let Ok(response) = services() if let Ok(response) = services()
.sending .sending
.send_federation_request( .send_federation_request(
@ -236,7 +235,7 @@ impl Service {
) )
.await .await
{ {
warn!( t::warn!(
%server, %server,
?response, ?response,
"Got response from other server for /hierarchy", "Got response from other server for /hierarchy",
@ -333,7 +332,7 @@ impl Service {
} }
#[allow(clippy::too_many_lines)] #[allow(clippy::too_many_lines)]
#[tracing::instrument(skip(self, children))] #[t::instrument(skip(self, children))]
fn get_room_chunk( fn get_room_chunk(
&self, &self,
sender_user: &UserId, sender_user: &UserId,
@ -353,7 +352,7 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomCanonicalAliasEventContent| c.alias) .map(|c: RoomCanonicalAliasEventContent| c.alias)
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room canonical alias event" "Invalid room canonical alias event"
@ -369,7 +368,7 @@ impl Service {
.state_cache .state_cache
.room_joined_count(room_id)? .room_joined_count(room_id)?
.unwrap_or_else(|| { .unwrap_or_else(|| {
warn!("Room has no member count"); t::warn!("Room has no member count");
0 0
}) })
.try_into() .try_into()
@ -383,7 +382,7 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomTopicEventContent| Some(c.topic)) .map(|c: RoomTopicEventContent| Some(c.topic))
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room topic event" "Invalid room topic event"
@ -408,7 +407,7 @@ impl Service {
== HistoryVisibility::WorldReadable == HistoryVisibility::WorldReadable
}) })
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room history visibility event" "Invalid room history visibility event"
@ -429,7 +428,7 @@ impl Service {
c.guest_access == GuestAccess::CanJoin c.guest_access == GuestAccess::CanJoin
}) })
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room guest access event" "Invalid room guest access event"
@ -447,7 +446,7 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomAvatarEventContent| c.url) .map(|c: RoomAvatarEventContent| c.url)
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room avatar event" "Invalid room avatar event"
@ -472,7 +471,7 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomJoinRulesEventContent| c.join_rule) .map(|c: RoomJoinRulesEventContent| c.join_rule)
.map_err(|error| { .map_err(|error| {
error!( t::error!(
%error, %error,
event_id = %s.event_id, event_id = %s.event_id,
"Invalid room join rule event", "Invalid room join rule event",
@ -486,7 +485,7 @@ impl Service {
.unwrap_or(JoinRule::Invite); .unwrap_or(JoinRule::Invite);
if !self.handle_join_rule(&join_rule, sender_user, room_id)? { 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 // This error will be caught later
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
@ -547,7 +546,7 @@ impl Service {
Ok(allowed) Ok(allowed)
} }
#[tracing::instrument(skip(self, sender_user))] #[t::instrument(skip(self, sender_user))]
fn handle_join_rule( fn handle_join_rule(
&self, &self,
join_rule: &JoinRule, join_rule: &JoinRule,

24
src/service/rooms/state.rs
View file

@ -16,10 +16,10 @@ use ruma::{
EventId, OwnedEventId, OwnedRoomId, RoomId, RoomVersionId, UserId, EventId, OwnedEventId, OwnedRoomId, RoomId, RoomVersionId, UserId,
}; };
use serde::{de::DeserializeOwned, Deserialize}; use serde::{de::DeserializeOwned, Deserialize};
use tracing::warn;
use super::{short::ShortStateHash, state_compressor::CompressedStateEvent}; use super::{short::ShortStateHash, state_compressor::CompressedStateEvent};
use crate::{ use crate::{
observability::prelude::*,
service::globals::marker, service::globals::marker,
services, services,
utils::{ utils::{
@ -86,7 +86,7 @@ pub(crate) struct Service {
impl Service { impl Service {
/// Set the room to the given statehash and update caches. /// 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( pub(crate) async fn force_state(
&self, &self,
room_id: &KeyToken<OwnedRoomId, marker::State>, room_id: &KeyToken<OwnedRoomId, marker::State>,
@ -170,7 +170,7 @@ impl Service {
/// ///
/// This adds all current state events (not including the incoming event) /// This adds all current state events (not including the incoming event)
/// to `stateid_pduid` and adds the incoming event to `eventid_statehash`. /// 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( pub(crate) fn set_event_state(
&self, &self,
event_id: &EventId, event_id: &EventId,
@ -237,7 +237,7 @@ impl Service {
/// ///
/// This adds all current state events (not including the incoming event) /// This adds all current state events (not including the incoming event)
/// to `stateid_pduid` and adds the incoming event to `eventid_statehash`. /// 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( pub(crate) fn append_to_state(
&self, &self,
new_pdu: &PduEvent, new_pdu: &PduEvent,
@ -319,7 +319,7 @@ impl Service {
/// Gather events to help the invited user identify the room /// Gather events to help the invited user identify the room
/// ///
/// Also includes the invite event itself. /// 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( pub(crate) fn get_helpful_invite_events(
&self, &self,
invite_event: &PduEvent, invite_event: &PduEvent,
@ -355,7 +355,7 @@ impl Service {
} }
/// Set the state hash to a new version, but does not update state_cache. /// 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( pub(crate) fn set_room_state(
&self, &self,
room_id: &KeyToken<OwnedRoomId, marker::State>, room_id: &KeyToken<OwnedRoomId, marker::State>,
@ -365,7 +365,7 @@ impl Service {
} }
/// Returns the value of a field of an `m.room.create` event's `content`. /// 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<T: ExtractCreateContent>( pub(crate) fn get_create_content<T: ExtractCreateContent>(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -381,7 +381,7 @@ impl Service {
.map(|create_event| { .map(|create_event| {
serde_json::from_str::<T>(create_event.content.get()).map_err( serde_json::from_str::<T>(create_event.content.get()).map_err(
|error| { |error| {
warn!(%error, "Invalid create event"); t::warn!(%error, "Invalid create event");
Error::BadDatabase("Invalid create event in db.") Error::BadDatabase("Invalid create event in db.")
}, },
) )
@ -397,7 +397,7 @@ impl Service {
Ok(content_field.extract()) Ok(content_field.extract())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_room_shortstatehash( pub(crate) fn get_room_shortstatehash(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -405,7 +405,7 @@ impl Service {
self.db.get_room_shortstatehash(room_id) self.db.get_room_shortstatehash(room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_forward_extremities( pub(crate) fn get_forward_extremities(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -413,7 +413,7 @@ impl Service {
self.db.get_forward_extremities(room_id) self.db.get_forward_extremities(room_id)
} }
#[tracing::instrument( #[t::instrument(
skip(self, event_ids), skip(self, event_ids),
fields(event_ids = debug_slice_truncated(&event_ids, 5)), fields(event_ids = debug_slice_truncated(&event_ids, 5)),
)] )]
@ -426,7 +426,7 @@ impl Service {
} }
/// This fetches auth events from the current state. /// This fetches auth events from the current state.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_auth_events( pub(crate) fn get_auth_events(
&self, &self,
room_id: &RoomId, room_id: &RoomId,

50
src/service/rooms/state_accessor.rs
View file

@ -22,11 +22,10 @@ use ruma::{
ServerName, UserId, ServerName, UserId,
}; };
use serde_json::value::to_raw_value; use serde_json::value::to_raw_value;
use tracing::{error, warn};
use super::short::{ShortStateHash, ShortStateKey}; use super::short::{ShortStateHash, ShortStateKey};
use crate::{ use crate::{
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
service::{globals::marker, pdu::PduBuilder}, service::{globals::marker, pdu::PduBuilder},
services, services,
utils::on_demand_hashmap::KeyToken, utils::on_demand_hashmap::KeyToken,
@ -63,7 +62,7 @@ impl Service {
/// Builds a StateMap by iterating over all keys that start /// Builds a StateMap by iterating over all keys that start
/// with state_hash, this gives the full state for the given state_hash. /// 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( pub(crate) async fn state_full_ids(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -92,7 +91,7 @@ impl Service {
Ok(result) Ok(result)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn state_full( pub(crate) async fn state_full(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -140,7 +139,7 @@ impl Service {
/// Returns a single PDU from `room_id` with key (`event_type`, /// Returns a single PDU from `room_id` with key (`event_type`,
/// `state_key`). /// `state_key`).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn state_get_id( pub(crate) fn state_get_id(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -174,7 +173,7 @@ impl Service {
/// Returns a single PDU from `room_id` with key (`event_type`, /// Returns a single PDU from `room_id` with key (`event_type`,
/// `state_key`). /// `state_key`).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn state_get( pub(crate) fn state_get(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -188,7 +187,7 @@ impl Service {
} }
/// Get membership for given user in state /// Get membership for given user in state
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn user_membership( fn user_membership(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -211,7 +210,7 @@ impl Service {
} }
/// The user was a joined member at this state (potentially in the past) /// 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( fn user_was_joined(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -223,7 +222,7 @@ impl Service {
/// The user was an invited or joined room member at this state (potentially /// The user was an invited or joined room member at this state (potentially
/// in the past) /// in the past)
#[tracing::instrument(skip(self), ret(level = "trace"))] #[t::instrument(skip(self), ret(level = "trace"))]
fn user_was_invited( fn user_was_invited(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -236,7 +235,7 @@ impl Service {
/// Whether a server is allowed to see an event through federation, based on /// Whether a server is allowed to see an event through federation, based on
/// the room's history_visibility at that event's state. /// 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( pub(crate) fn server_can_see_event(
&self, &self,
origin: &ServerName, origin: &ServerName,
@ -302,7 +301,7 @@ impl Service {
.any(|member| self.user_was_joined(shortstatehash, &member)) .any(|member| self.user_was_joined(shortstatehash, &member))
} }
other => { other => {
error!(kind = %other, "Unknown history visibility"); t::error!(kind = %other, "Unknown history visibility");
false false
} }
}; };
@ -321,7 +320,7 @@ impl Service {
/// Whether a user is allowed to see an event, based on /// Whether a user is allowed to see an event, based on
/// the room's history_visibility at that event's state. /// 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( pub(crate) fn user_can_see_event(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -379,7 +378,7 @@ impl Service {
self.user_was_joined(shortstatehash, user_id) self.user_was_joined(shortstatehash, user_id)
} }
other => { other => {
error!(kind = %other, "Unknown history visibility"); t::error!(kind = %other, "Unknown history visibility");
false false
} }
}; };
@ -398,7 +397,7 @@ impl Service {
/// Whether a user is allowed to see an event, based on /// Whether a user is allowed to see an event, based on
/// the room's history_visibility at that event's state. /// 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( pub(crate) fn user_can_see_state_events(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -430,7 +429,7 @@ impl Service {
} }
/// Returns the state hash for this pdu. /// Returns the state hash for this pdu.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn pdu_shortstatehash( pub(crate) fn pdu_shortstatehash(
&self, &self,
event_id: &EventId, event_id: &EventId,
@ -439,7 +438,7 @@ impl Service {
} }
/// Returns the full room state. /// Returns the full room state.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn room_state_full( pub(crate) async fn room_state_full(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -455,7 +454,7 @@ impl Service {
/// Returns a single PDU from `room_id` with key (`event_type`, /// Returns a single PDU from `room_id` with key (`event_type`,
/// `state_key`). /// `state_key`).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_state_get_id( pub(crate) fn room_state_get_id(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -473,7 +472,7 @@ impl Service {
/// Returns a single PDU from `room_id` with key (`event_type`, /// Returns a single PDU from `room_id` with key (`event_type`,
/// `state_key`). /// `state_key`).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_state_get( pub(crate) fn room_state_get(
&self, &self,
room_id: &RoomId, 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<Option<String>> { pub(crate) fn get_name(&self, room_id: &RoomId) -> Result<Option<String>> {
self.room_state_get(room_id, &StateEventType::RoomName, "")?.map_or( self.room_state_get(room_id, &StateEventType::RoomName, "")?.map_or(
Ok(None), Ok(None),
@ -497,7 +496,10 @@ impl Service {
serde_json::from_str(s.content.get()) serde_json::from_str(s.content.get())
.map(|c: RoomNameEventContent| Some(c.name)) .map(|c: RoomNameEventContent| Some(c.name))
.map_err(|error| { .map_err(|error| {
error!(%error, "Invalid room name event in database"); t::error!(
%error,
"Invalid room name event in database"
);
Error::BadDatabase( Error::BadDatabase(
"Invalid room name event in database.", "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( pub(crate) fn get_avatar(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -525,7 +527,7 @@ impl Service {
// Allowed because this function uses `services()` // Allowed because this function uses `services()`
#[allow(clippy::unused_self)] #[allow(clippy::unused_self)]
#[tracing::instrument(skip(self), ret(level = "trace"))] #[t::instrument(skip(self), ret(level = "trace"))]
pub(crate) fn user_can_invite( pub(crate) fn user_can_invite(
&self, &self,
room_id: &KeyToken<OwnedRoomId, marker::State>, room_id: &KeyToken<OwnedRoomId, marker::State>,
@ -551,7 +553,7 @@ impl Service {
.is_ok() .is_ok()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_member( pub(crate) fn get_member(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -574,7 +576,7 @@ impl Service {
/// If `federation` is `true`, it allows redaction events from any user of /// If `federation` is `true`, it allows redaction events from any user of
/// the same server as the original event sender, [as required by room /// the same server as the original event sender, [as required by room
/// versions >= v3](https://spec.matrix.org/v1.10/rooms/v11/#handling-redactions) /// 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( pub(crate) fn user_can_redact(
&self, &self,
redacts: &EventId, redacts: &EventId,

66
src/service/rooms/state_cache.rs
View file

@ -12,10 +12,9 @@ use ruma::{
serde::Raw, serde::Raw,
OwnedRoomId, OwnedServerName, OwnedUserId, RoomId, ServerName, UserId, OwnedRoomId, OwnedServerName, OwnedUserId, RoomId, ServerName, UserId,
}; };
use tracing::warn;
use crate::{ use crate::{
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
service::appservice::RegistrationInfo, service::appservice::RegistrationInfo,
services, Error, Result, services, Error, Result,
}; };
@ -46,7 +45,7 @@ impl Service {
} }
/// Update current membership data. /// Update current membership data.
#[tracing::instrument(skip(self, last_state))] #[t::instrument(skip(self, last_state))]
pub(crate) fn update_membership( pub(crate) fn update_membership(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -76,7 +75,7 @@ impl Service {
.state .state
.get_create_content::<ExtractPredecessor>(room_id) .get_create_content::<ExtractPredecessor>(room_id)
.inspect_err(|error| { .inspect_err(|error| {
warn!(%error, "Failed to get room predecessor"); t::warn!(%error, "Failed to get room predecessor");
}) })
.ok() .ok()
.flatten() .flatten()
@ -111,7 +110,7 @@ impl Service {
event.get(), event.get(),
) )
.map_err(|error| { .map_err(|error| {
warn!( t::warn!(
%error, %error,
%event_kind, %event_kind,
"Invalid account data event", "Invalid account data event",
@ -151,7 +150,7 @@ impl Service {
/// joining an upgraded room. /// joining an upgraded room.
/// ///
/// References to the predecessor room are not removed. /// References to the predecessor room are not removed.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
fn copy_upgraded_account_data( fn copy_upgraded_account_data(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -216,7 +215,10 @@ impl Service {
RoomAccountDataEventType::Tag, RoomAccountDataEventType::Tag,
&event, &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(()) Ok(())
@ -291,13 +293,17 @@ impl Service {
event_kind.clone(), event_kind.clone(),
&event, &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(()) Ok(())
} }
#[tracing::instrument(skip(self, room_id))] #[t::instrument(skip(self, room_id))]
pub(crate) fn update_joined_count( pub(crate) fn update_joined_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -313,7 +319,7 @@ impl Service {
Ok(our_real_users) Ok(our_real_users)
} }
#[tracing::instrument(skip(self, room_id))] #[t::instrument(skip(self, room_id))]
pub(crate) fn get_our_real_users( pub(crate) fn get_our_real_users(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -334,7 +340,7 @@ impl Service {
Ok(our_real_users) Ok(our_real_users)
} }
#[tracing::instrument(skip(self, room_id, appservice))] #[t::instrument(skip(self, room_id, appservice))]
pub(crate) fn appservice_in_room( pub(crate) fn appservice_in_room(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -368,7 +374,7 @@ impl Service {
} }
/// Makes a user forget a room. /// Makes a user forget a room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn forget( pub(crate) fn forget(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -378,7 +384,7 @@ impl Service {
} }
/// Returns an iterator of all servers participating in this room. /// Returns an iterator of all servers participating in this room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_servers<'a>( pub(crate) fn room_servers<'a>(
&'a self, &'a self,
room_id: &RoomId, room_id: &RoomId,
@ -386,7 +392,7 @@ impl Service {
self.db.room_servers(room_id) self.db.room_servers(room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn server_in_room( pub(crate) fn server_in_room(
&self, &self,
server: &ServerName, server: &ServerName,
@ -397,7 +403,7 @@ impl Service {
/// Returns an iterator of all rooms a server participates in (as far as we /// Returns an iterator of all rooms a server participates in (as far as we
/// know). /// know).
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn server_rooms<'a>( pub(crate) fn server_rooms<'a>(
&'a self, &'a self,
server: &ServerName, server: &ServerName,
@ -406,7 +412,7 @@ impl Service {
} }
/// Returns an iterator over all joined members of a room. /// Returns an iterator over all joined members of a room.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_members<'a>( pub(crate) fn room_members<'a>(
&'a self, &'a self,
room_id: &RoomId, room_id: &RoomId,
@ -414,7 +420,7 @@ impl Service {
self.db.room_members(room_id) self.db.room_members(room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_joined_count( pub(crate) fn room_joined_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -422,7 +428,7 @@ impl Service {
self.db.room_joined_count(room_id) self.db.room_joined_count(room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn room_invited_count( pub(crate) fn room_invited_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -431,7 +437,7 @@ impl Service {
} }
/// Returns an iterator over all invited members of a room. /// 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>( pub(crate) fn room_members_invited<'a>(
&'a self, &'a self,
room_id: &RoomId, room_id: &RoomId,
@ -439,7 +445,7 @@ impl Service {
self.db.room_members_invited(room_id) self.db.room_members_invited(room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_invite_count( pub(crate) fn get_invite_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -448,7 +454,7 @@ impl Service {
self.db.get_invite_count(room_id, user_id) self.db.get_invite_count(room_id, user_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_left_count( pub(crate) fn get_left_count(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -458,7 +464,7 @@ impl Service {
} }
/// Returns an iterator over all rooms this user joined. /// Returns an iterator over all rooms this user joined.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn rooms_joined<'a>( pub(crate) fn rooms_joined<'a>(
&'a self, &'a self,
user_id: &UserId, user_id: &UserId,
@ -467,7 +473,7 @@ impl Service {
} }
/// Returns an iterator over all rooms a user was invited to. /// 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>( pub(crate) fn rooms_invited<'a>(
&'a self, &'a self,
user_id: &UserId, user_id: &UserId,
@ -477,7 +483,7 @@ impl Service {
self.db.rooms_invited(user_id) self.db.rooms_invited(user_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn invite_state( pub(crate) fn invite_state(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -486,7 +492,7 @@ impl Service {
self.db.invite_state(user_id, room_id) self.db.invite_state(user_id, room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn left_state( pub(crate) fn left_state(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -496,7 +502,7 @@ impl Service {
} }
/// Returns an iterator over all rooms a user left. /// Returns an iterator over all rooms a user left.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn rooms_left<'a>( pub(crate) fn rooms_left<'a>(
&'a self, &'a self,
user_id: &UserId, user_id: &UserId,
@ -504,7 +510,7 @@ impl Service {
self.db.rooms_left(user_id) self.db.rooms_left(user_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn once_joined( pub(crate) fn once_joined(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -513,7 +519,7 @@ impl Service {
self.db.once_joined(user_id, room_id) self.db.once_joined(user_id, room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn is_joined( pub(crate) fn is_joined(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -522,7 +528,7 @@ impl Service {
self.db.is_joined(user_id, room_id) self.db.is_joined(user_id, room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn is_invited( pub(crate) fn is_invited(
&self, &self,
user_id: &UserId, user_id: &UserId,
@ -531,7 +537,7 @@ impl Service {
self.db.is_invited(user_id, room_id) self.db.is_invited(user_id, room_id)
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn is_left( pub(crate) fn is_left(
&self, &self,
user_id: &UserId, user_id: &UserId,

8
src/service/rooms/state_compressor.rs
View file

@ -10,7 +10,7 @@ use ruma::{EventId, RoomId};
use super::short::{ShortEventId, ShortStateHash, ShortStateKey}; use super::short::{ShortEventId, ShortStateHash, ShortStateKey};
use crate::{ use crate::{
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
services, utils, Result, services, utils, Result,
}; };
@ -86,7 +86,7 @@ impl Service {
/// Returns a stack with info on shortstatehash, full state, added diff and /// Returns a stack with info on shortstatehash, full state, added diff and
/// removed diff for the selected shortstatehash and each parent layer. /// removed diff for the selected shortstatehash and each parent layer.
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn load_shortstatehash_info( pub(crate) fn load_shortstatehash_info(
&self, &self,
shortstatehash: ShortStateHash, shortstatehash: ShortStateHash,
@ -191,7 +191,7 @@ impl Service {
/// * `parent_states` - A stack with info on shortstatehash, full state, /// * `parent_states` - A stack with info on shortstatehash, full state,
/// added diff and removed diff for each parent layer /// added diff and removed diff for each parent layer
#[allow(clippy::type_complexity)] #[allow(clippy::type_complexity)]
#[tracing::instrument(skip( #[t::instrument(skip(
self, self,
statediffnew, statediffnew,
statediffremoved, statediffremoved,
@ -314,7 +314,7 @@ impl Service {
/// Returns the new shortstatehash, and the state diff from the previous /// Returns the new shortstatehash, and the state diff from the previous
/// room state /// room state
#[allow(clippy::type_complexity)] #[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( pub(crate) fn save_state(
&self, &self,
room_id: &RoomId, room_id: &RoomId,

57
src/service/rooms/timeline.rs
View file

@ -26,12 +26,11 @@ use ruma::{
use serde::Deserialize; use serde::Deserialize;
use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use serde_json::value::{to_raw_value, RawValue as RawJsonValue};
use tokio::sync::RwLock; use tokio::sync::RwLock;
use tracing::{error, info, warn};
use super::{short::ShortRoomId, state_compressor::CompressedStateEvent}; use super::{short::ShortRoomId, state_compressor::CompressedStateEvent};
use crate::{ use crate::{
api::server_server, api::server_server,
observability::{FoundIn, Lookup, METRICS}, observability::{prelude::*, FoundIn, Lookup, METRICS},
service::{ service::{
appservice::NamespaceRegex, appservice::NamespaceRegex,
globals::{marker, SigningKeys}, globals::{marker, SigningKeys},
@ -131,7 +130,7 @@ impl Service {
} }
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn first_pdu_in_room( pub(crate) fn first_pdu_in_room(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -142,7 +141,7 @@ impl Service {
.transpose() .transpose()
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn last_timeline_count( pub(crate) fn last_timeline_count(
&self, &self,
sender_user: &UserId, sender_user: &UserId,
@ -162,7 +161,7 @@ impl Service {
.find_map(|x| match x { .find_map(|x| match x {
Ok(x) => Some(x), Ok(x) => Some(x),
Err(error) => { Err(error) => {
error!(%error, "Bad pdu in pdus_since"); t::error!(%error, "Bad pdu in pdus_since");
None None
} }
}) })
@ -259,7 +258,7 @@ impl Service {
} }
/// Removes a pdu and creates a new one with the same id. /// 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( pub(crate) fn replace_pdu(
&self, &self,
pdu_id: &PduId, pdu_id: &PduId,
@ -277,7 +276,7 @@ impl Service {
/// happens in `append_pdu`. /// happens in `append_pdu`.
/// ///
/// Returns pdu id /// 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( pub(crate) async fn append_pdu(
&self, &self,
pdu: &PduEvent, pdu: &PduEvent,
@ -331,7 +330,7 @@ impl Service {
} }
} }
} else { } else {
error!("Invalid unsigned type in pdu"); t::error!("Invalid unsigned type in pdu");
} }
} }
@ -555,7 +554,7 @@ impl Service {
if user.server_name() if user.server_name()
== services().globals.server_name() == services().globals.server_name()
{ {
info!( t::info!(
%user, %user,
%room, %room,
reason, reason,
@ -880,7 +879,7 @@ impl Service {
|k, s| auth_events.get(&(k.clone(), s.to_owned())), |k, s| auth_events.get(&(k.clone(), s.to_owned())),
) )
.map_err(|error| { .map_err(|error| {
error!(%error, "Auth check failed"); t::error!(%error, "Auth check failed");
Error::BadDatabase("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 /// 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 /// takes a roomid_mutex_state, meaning that only this function is able
/// to mutate the room state. /// to mutate the room state.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) async fn build_and_append_pdu( pub(crate) async fn build_and_append_pdu(
&self, &self,
pdu_builder: PduBuilder, pdu_builder: PduBuilder,
@ -962,7 +961,9 @@ impl Service {
if admin_room == **room_id { if admin_room == **room_id {
match pdu.event_type() { match pdu.event_type() {
TimelineEventType::RoomEncryption => { 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( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Encryption is not allowed in the admins room.", "Encryption is not allowed in the admins room.",
@ -997,7 +998,7 @@ impl Service {
if content.membership == MembershipState::Leave { if content.membership == MembershipState::Leave {
if target == server_user { if target == server_user {
warn!( t::warn!(
"Grapevine user cannot leave from admins \ "Grapevine user cannot leave from admins \
room" room"
); );
@ -1017,7 +1018,7 @@ impl Service {
.filter(|m| m != target) .filter(|m| m != target)
.count(); .count();
if count < 2 { if count < 2 {
warn!( t::warn!(
"Last admin cannot leave from admins room" "Last admin cannot leave from admins room"
); );
return Err(Error::BadRequest( return Err(Error::BadRequest(
@ -1031,7 +1032,7 @@ impl Service {
&& pdu.state_key().is_some() && pdu.state_key().is_some()
{ {
if target == server_user { if target == server_user {
warn!( t::warn!(
"Grapevine user cannot be banned in \ "Grapevine user cannot be banned in \
admins room" admins room"
); );
@ -1051,7 +1052,7 @@ impl Service {
.filter(|m| m != target) .filter(|m| m != target)
.count(); .count();
if count < 2 { if count < 2 {
warn!( t::warn!(
"Last admin cannot be banned in admins \ "Last admin cannot be banned in admins \
room" room"
); );
@ -1164,7 +1165,7 @@ impl Service {
/// Append the incoming event setting the state snapshot to the state from /// Append the incoming event setting the state snapshot to the state from
/// the server that sent the event. /// the server that sent the event.
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
pub(crate) async fn append_incoming_pdu( pub(crate) async fn append_incoming_pdu(
&self, &self,
pdu: &PduEvent, pdu: &PduEvent,
@ -1215,7 +1216,7 @@ impl Service {
/// Returns an iterator over all events and their tokens in a room that /// Returns an iterator over all events and their tokens in a room that
/// happened before the event with id `until` in reverse-chronological /// happened before the event with id `until` in reverse-chronological
/// order. /// order.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn pdus_until<'a>( pub(crate) fn pdus_until<'a>(
&'a self, &'a self,
user_id: &UserId, user_id: &UserId,
@ -1227,7 +1228,7 @@ impl Service {
/// Returns an iterator over all events and their token in a room that /// Returns an iterator over all events and their token in a room that
/// happened after the event with id `from` in chronological order. /// happened after the event with id `from` in chronological order.
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn pdus_after<'a>( pub(crate) fn pdus_after<'a>(
&'a self, &'a self,
user_id: &UserId, user_id: &UserId,
@ -1238,7 +1239,7 @@ impl Service {
} }
/// Replace a PDU with the redacted form. /// Replace a PDU with the redacted form.
#[tracing::instrument(skip(self, reason))] #[t::instrument(skip(self, reason))]
pub(crate) fn redact_pdu( pub(crate) fn redact_pdu(
&self, &self,
event_id: &EventId, event_id: &EventId,
@ -1282,7 +1283,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, room_id))] #[t::instrument(skip(self, room_id))]
pub(crate) async fn backfill_if_required( pub(crate) async fn backfill_if_required(
&self, &self,
room_id: &RoomId, room_id: &RoomId,
@ -1319,7 +1320,7 @@ impl Service {
// Request backfill // Request backfill
for backfill_server in admin_servers { 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() let response = services()
.sending .sending
.send_federation_request( .send_federation_request(
@ -1339,13 +1340,13 @@ impl Service {
.backfill_pdu(backfill_server, pdu, &pub_key_map) .backfill_pdu(backfill_server, pdu, &pub_key_map)
.await .await
{ {
warn!(%error, "Failed to add backfilled pdu"); t::warn!(%error, "Failed to add backfilled pdu");
} }
} }
return Ok(()); return Ok(());
} }
Err(error) => { Err(error) => {
warn!( t::warn!(
server = %backfill_server, server = %backfill_server,
%error, %error,
"Server could not provide backfill", "Server could not provide backfill",
@ -1354,11 +1355,11 @@ impl Service {
} }
} }
info!("No servers could backfill"); t::info!("No servers could backfill");
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, pdu))] #[t::instrument(skip(self, pdu))]
pub(crate) async fn backfill_pdu( pub(crate) async fn backfill_pdu(
&self, &self,
origin: &ServerName, origin: &ServerName,
@ -1377,7 +1378,7 @@ impl Service {
// Skip the PDU if we already have it as a timeline event // Skip the PDU if we already have it as a timeline event
if let Some(pdu_id) = self.get_pdu_id(&event_id)? { 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(()); return Ok(());
} }
@ -1442,7 +1443,7 @@ impl Service {
} }
drop(federation_token); drop(federation_token);
info!("Prepended backfill pdu"); t::info!("Prepended backfill pdu");
Ok(()) Ok(())
} }
} }

62
src/service/sending.rs
View file

@ -34,7 +34,7 @@ use tokio::{
select, select,
sync::{mpsc, Mutex, Semaphore}, sync::{mpsc, Mutex, Semaphore},
}; };
use tracing::{debug, error, warn, Span}; use tracing::Span;
use super::rooms::timeline::PduId; use super::rooms::timeline::PduId;
use crate::{ use crate::{
@ -42,6 +42,7 @@ use crate::{
appservice_server, appservice_server,
server_server::{self, AllowLoopbackRequests, LogRequestError}, server_server::{self, AllowLoopbackRequests, LogRequestError},
}, },
observability::prelude::*,
services, services,
utils::{calculate_hash, debug_slice_truncated}, utils::{calculate_hash, debug_slice_truncated},
Config, Error, PduEvent, Result, Config, Error, PduEvent, Result,
@ -60,7 +61,7 @@ pub(crate) enum Destination {
} }
impl Destination { impl Destination {
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn get_prefix(&self) -> Vec<u8> { pub(crate) fn get_prefix(&self) -> Vec<u8> {
let mut prefix = match self { let mut prefix = match self {
Destination::Appservice(server) => { Destination::Appservice(server) => {
@ -196,7 +197,7 @@ impl Service {
initial_transactions.entry(destination.clone()).or_default(); initial_transactions.entry(destination.clone()).or_default();
if entry.len() > 30 { if entry.len() > 30 {
warn!( t::warn!(
?key, ?key,
?destination, ?destination,
?event, ?event,
@ -240,7 +241,7 @@ impl Service {
} }
} }
#[tracing::instrument( #[t::instrument(
skip(self, result, handler_span, current_transaction_status), skip(self, result, handler_span, current_transaction_status),
fields( fields(
current_status = ?current_transaction_status.get( current_status = ?current_transaction_status.get(
@ -266,7 +267,7 @@ impl Service {
} }
if let Err(error) = result { 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| { current_transaction_status.entry(destination).and_modify(|e| {
use TransactionStatus::{Failed, Retrying, Running}; use TransactionStatus::{Failed, Retrying, Running};
@ -274,7 +275,7 @@ impl Service {
Running => Failed(1, Instant::now()), Running => Failed(1, Instant::now()),
Retrying(n) => Failed(*n + 1, Instant::now()), Retrying(n) => Failed(*n + 1, Instant::now()),
Failed(..) => { Failed(..) => {
error!("Request that was not even running failed?!"); t::error!("Request that was not even running failed?!");
return; return;
} }
} }
@ -308,7 +309,7 @@ impl Service {
})) }))
} }
#[tracing::instrument( #[t::instrument(
skip(self, event_type, key, requester_span, current_transaction_status), skip(self, event_type, key, requester_span, current_transaction_status),
fields( fields(
current_status = ?current_transaction_status.get(&destination), current_status = ?current_transaction_status.get(&destination),
@ -333,7 +334,7 @@ impl Service {
current_transaction_status, current_transaction_status,
) { ) {
Ok(SelectedEvents::Retries(events)) => { Ok(SelectedEvents::Retries(events)) => {
debug!("Retrying old events"); t::debug!("Retrying old events");
Some(HandlerInputs { Some(HandlerInputs {
destination, destination,
events, events,
@ -341,7 +342,7 @@ impl Service {
}) })
} }
Ok(SelectedEvents::New(events)) => { Ok(SelectedEvents::New(events)) => {
debug!("Sending new event"); t::debug!("Sending new event");
Some(HandlerInputs { Some(HandlerInputs {
destination, destination,
events, events,
@ -349,17 +350,17 @@ impl Service {
}) })
} }
Ok(SelectedEvents::None) => { Ok(SelectedEvents::None) => {
debug!("Holding off from sending any events"); t::debug!("Holding off from sending any events");
None None
} }
Err(error) => { Err(error) => {
error!(%error, "Failed to select events to send"); t::error!(%error, "Failed to select events to send");
None None
} }
} }
} }
#[tracing::instrument( #[t::instrument(
skip(self, new_events, current_transaction_status), skip(self, new_events, current_transaction_status),
fields( fields(
new_events = debug_slice_truncated(&new_events, 3), 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( pub(crate) fn select_edus(
&self, &self,
server_name: &ServerName, server_name: &ServerName,
@ -567,7 +568,7 @@ impl Service {
Ok((events, max_edu_count)) 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( pub(crate) fn send_push_pdu(
&self, &self,
pdu_id: &PduId, pdu_id: &PduId,
@ -590,7 +591,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, servers, pdu_id))] #[t::instrument(skip(self, servers, pdu_id))]
pub(crate) fn send_pdu<I: Iterator<Item = OwnedServerName>>( pub(crate) fn send_pdu<I: Iterator<Item = OwnedServerName>>(
&self, &self,
servers: I, servers: I,
@ -622,7 +623,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, server, serialized))] #[t::instrument(skip(self, server, serialized))]
pub(crate) fn send_reliable_edu( pub(crate) fn send_reliable_edu(
&self, &self,
server: &ServerName, server: &ServerName,
@ -645,7 +646,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self))] #[t::instrument(skip(self))]
pub(crate) fn send_pdu_appservice( pub(crate) fn send_pdu_appservice(
&self, &self,
appservice_id: String, appservice_id: String,
@ -667,7 +668,7 @@ impl Service {
Ok(()) Ok(())
} }
#[tracing::instrument(skip(self, request))] #[t::instrument(skip(self, request))]
pub(crate) async fn send_federation_request<T>( pub(crate) async fn send_federation_request<T>(
&self, &self,
destination: &ServerName, destination: &ServerName,
@ -676,9 +677,9 @@ impl Service {
where where
T: OutgoingRequest + Debug, T: OutgoingRequest + Debug,
{ {
debug!("Waiting for permit"); t::debug!("Waiting for permit");
let permit = self.maximum_requests.acquire().await; let permit = self.maximum_requests.acquire().await;
debug!("Got permit"); t::debug!("Got permit");
let response = tokio::time::timeout( let response = tokio::time::timeout(
Duration::from_secs(2 * 60), Duration::from_secs(2 * 60),
server_server::send_request( server_server::send_request(
@ -690,7 +691,7 @@ impl Service {
) )
.await .await
.map_err(|_| { .map_err(|_| {
warn!("Timeout waiting for server response"); t::warn!("Timeout waiting for server response");
Error::BadServerResponse("Timeout waiting for server response") Error::BadServerResponse("Timeout waiting for server response")
})?; })?;
drop(permit); drop(permit);
@ -702,7 +703,7 @@ impl Service {
/// ///
/// Only returns None if there is no url specified in the appservice /// Only returns None if there is no url specified in the appservice
/// registration file /// registration file
#[tracing::instrument( #[t::instrument(
skip(self, registration, request), skip(self, registration, request),
fields(appservice_id = registration.id), fields(appservice_id = registration.id),
)] )]
@ -723,7 +724,7 @@ impl Service {
} }
} }
#[tracing::instrument(skip(events))] #[t::instrument(skip(events))]
async fn handle_appservice_event( async fn handle_appservice_event(
id: &str, id: &str,
events: Vec<SendingEventType>, events: Vec<SendingEventType>,
@ -778,7 +779,7 @@ async fn handle_appservice_event(
Ok(()) Ok(())
} }
#[tracing::instrument(skip(events))] #[t::instrument(skip(events))]
async fn handle_push_event( async fn handle_push_event(
userid: &UserId, userid: &UserId,
pushkey: &str, pushkey: &str,
@ -861,7 +862,7 @@ async fn handle_push_event(
Ok(()) Ok(())
} }
#[tracing::instrument(skip(events))] #[t::instrument(skip(events))]
async fn handle_federation_event( async fn handle_federation_event(
server: &ServerName, server: &ServerName,
events: Vec<SendingEventType>, events: Vec<SendingEventType>,
@ -880,7 +881,7 @@ async fn handle_federation_event(
.timeline .timeline
.get_pdu_json_from_id(pdu_id)? .get_pdu_json_from_id(pdu_id)?
.ok_or_else(|| { .ok_or_else(|| {
error!(pdu_id = ?pdu_id, "PDU not found"); t::error!(pdu_id = ?pdu_id, "PDU not found");
Error::bad_database( Error::bad_database(
"[Normal] Event in servernamevent_datas not \ "[Normal] Event in servernamevent_datas not \
found in db.", found in db.",
@ -917,7 +918,12 @@ async fn handle_federation_event(
for pdu in response.pdus { for pdu in response.pdus {
if let (event_id, Err(error)) = pdu { 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(()) Ok(())
} }
#[tracing::instrument(skip_all)] #[t::instrument(skip_all)]
async fn handle_events( async fn handle_events(
HandlerInputs { HandlerInputs {
destination, destination,

6
src/service/uiaa.rs
View file

@ -7,10 +7,10 @@ use ruma::{
}, },
CanonicalJsonValue, DeviceId, OwnedDeviceId, OwnedUserId, UserId, CanonicalJsonValue, DeviceId, OwnedDeviceId, OwnedUserId, UserId,
}; };
use tracing::error;
use crate::{ 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; mod data;
@ -137,7 +137,7 @@ impl Service {
AuthData::Dummy(_) => { AuthData::Dummy(_) => {
uiaainfo.completed.push(AuthType::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 // Check if a flow now succeeds

8
src/utils.rs
View file

@ -15,7 +15,7 @@ use ruma::{
CanonicalJsonError, CanonicalJsonObject, MxcUri, MxcUriError, OwnedMxcUri, CanonicalJsonError, CanonicalJsonObject, MxcUri, MxcUriError, OwnedMxcUri,
}; };
use crate::{Error, Result}; use crate::{observability::prelude::*, Error, Result};
pub(crate) mod error; pub(crate) mod error;
pub(crate) mod on_demand_hashmap; pub(crate) mod on_demand_hashmap;
@ -108,7 +108,7 @@ where
Argon2::default().verify_password(password.as_ref(), &hash).is_ok() 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<u8> pub(crate) fn calculate_hash<'a, I, T>(keys: I) -> Vec<u8>
where where
I: IntoIterator<Item = T>, I: IntoIterator<Item = T>,
@ -234,8 +234,8 @@ impl<T: fmt::Debug> fmt::Debug for TruncatedDebugSlice<'_, T> {
pub(crate) fn debug_slice_truncated<T: fmt::Debug>( pub(crate) fn debug_slice_truncated<T: fmt::Debug>(
slice: &[T], slice: &[T],
max_len: usize, max_len: usize,
) -> tracing::field::DebugValue<TruncatedDebugSlice<'_, T>> { ) -> t::field::DebugValue<TruncatedDebugSlice<'_, T>> {
tracing::field::debug(TruncatedDebugSlice { t::field::debug(TruncatedDebugSlice {
inner: slice, inner: slice,
max_len, max_len,
}) })

9
src/utils/error.rs
View file

@ -9,9 +9,8 @@ use ruma::{
OwnedServerName, OwnedServerName,
}; };
use thiserror::Error; use thiserror::Error;
use tracing::{error, warn};
use crate::Ra; use crate::{observability::prelude::*, Ra};
pub(crate) type Result<T, E = Error> = std::result::Result<T, E>; pub(crate) type Result<T, E = Error> = std::result::Result<T, E>;
@ -88,12 +87,12 @@ pub(crate) enum Error {
impl Error { impl Error {
pub(crate) fn bad_database(message: &'static str) -> Self { pub(crate) fn bad_database(message: &'static str) -> Self {
error!(message, "Bad database"); t::error!(message, "Bad database");
Self::BadDatabase(message) Self::BadDatabase(message)
} }
pub(crate) fn bad_config(message: &'static str) -> Self { pub(crate) fn bad_config(message: &'static str) -> Self {
error!(message, "Bad config"); t::error!(message, "Bad config");
Self::BadConfig(message) Self::BadConfig(message)
} }
@ -156,7 +155,7 @@ impl Error {
_ => (Unknown, StatusCode::INTERNAL_SERVER_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 { Ra(UiaaResponse::MatrixError(RumaError {
body: ErrorBody::Standard { body: ErrorBody::Standard {

33
src/utils/on_demand_hashmap.rs
View file

@ -8,9 +8,8 @@ use std::{
}; };
use tokio::sync::{mpsc, Mutex, OwnedMutexGuard, RwLock}; 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 /// Data shared between [`OnDemandHashMap`] and the cleanup task
/// ///
@ -28,8 +27,8 @@ impl<K, V> SharedData<K, V>
where where
K: Hash + Eq + Clone + fmt::Debug, K: Hash + Eq + Clone + fmt::Debug,
{ {
#[tracing::instrument( #[t::instrument(
level = Level::TRACE, level = t::Level::TRACE,
skip(self), skip(self),
fields(name = self.name.as_ref()), fields(name = self.name.as_ref()),
)] )]
@ -37,21 +36,21 @@ where
let mut map = self.entries.write().await; let mut map = self.entries.write().await;
let Some(weak) = map.get(&key) else { let Some(weak) = map.get(&key) else {
trace!("Entry has already been cleaned up"); t::trace!("Entry has already been cleaned up");
return; return;
}; };
if weak.strong_count() != 0 { if weak.strong_count() != 0 {
trace!("Entry is in use"); t::trace!("Entry is in use");
return; return;
} }
trace!("Cleaning up unused entry"); t::trace!("Cleaning up unused entry");
map.remove(&key); map.remove(&key);
METRICS.record_on_demand_hashmap_size(self.name.clone(), map.len()); 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( fn try_get_live_value(
pass: usize, pass: usize,
map: &HashMap<K, Weak<V>>, map: &HashMap<K, Weak<V>>,
@ -59,16 +58,16 @@ where
) -> Option<Arc<V>> { ) -> Option<Arc<V>> {
if let Some(value) = map.get(key) { if let Some(value) = map.get(key) {
if let Some(value) = value.upgrade() { if let Some(value) = value.upgrade() {
trace!(pass, "Using existing value"); t::trace!(pass, "Using existing value");
return Some(value); return Some(value);
} }
trace!( t::trace!(
pass, pass,
"Existing value is stale and needs cleanup, creating new" "Existing value is stale and needs cleanup, creating new"
); );
} else { } else {
trace!(pass, "No existing value, creating new"); t::trace!(pass, "No existing value, creating new");
} }
None None
@ -76,7 +75,7 @@ where
/// Either returns an existing live value, or creates a new one and inserts /// Either returns an existing live value, or creates a new one and inserts
/// it into the map. /// 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<F>(&self, key: &K, create: F) -> Arc<V> async fn get_or_insert_with<F>(&self, key: &K, create: F) -> Arc<V>
where where
F: FnOnce() -> V, F: FnOnce() -> V,
@ -145,7 +144,7 @@ where
tokio::task::spawn(async move { tokio::task::spawn(async move {
loop { loop {
let Some(key) = receiver.recv().await else { let Some(key) = receiver.recv().await else {
trace!( t::trace!(
name = shared.name.as_ref(), name = shared.name.as_ref(),
"Channel has died, exiting cleanup task" "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<F>( pub(crate) async fn get_or_insert_with<F>(
&self, &self,
key: K, key: K,
@ -193,14 +192,14 @@ struct EntryDropGuard<K> {
impl<K> Drop for EntryDropGuard<K> { impl<K> Drop for EntryDropGuard<K> {
fn drop(&mut self) { fn drop(&mut self) {
let Some(cleanup_sender) = self.cleanup_sender.upgrade() else { 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; return;
}; };
if let Err(error) = cleanup_sender if let Err(error) = cleanup_sender
.send(self.key.take().expect("drop should only be called once")) .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 /// Locks this key in the `TokenSet`, returning a token proving
/// unique access. /// 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<K, M> { pub(crate) async fn lock_key(&self, key: K) -> KeyToken<K, M> {
let Entry { let Entry {
drop_guard, drop_guard,

10
src/utils/proxy_protocol.rs
View file

@ -11,7 +11,8 @@ use tokio::{
time::{timeout, Timeout}, time::{timeout, Timeout},
}; };
use tower::Layer; use tower::Layer;
use tracing::warn;
use crate::observability::prelude::*;
#[derive(Debug, Clone)] #[derive(Debug, Clone)]
pub(crate) struct ProxyAcceptorConfig { pub(crate) struct ProxyAcceptorConfig {
@ -138,13 +139,16 @@ where
let stream = ret let stream = ret
.map_err(|e| { .map_err(|e| {
warn!( t::warn!(
"Timed out waiting for HAProxy protocol header" "Timed out waiting for HAProxy protocol header"
); );
std::io::Error::new(ErrorKind::TimedOut, e) std::io::Error::new(ErrorKind::TimedOut, e)
})? })?
.inspect_err(|error| { .inspect_err(|error| {
warn!(%error, "Failed to parse HAProxy protocol header"); t::warn!(
%error,
"Failed to parse HAProxy protocol header"
);
})?; })?;
let service = let service =