From aff5d8532f923bd99a3ba2c4be9b468a54802933 Mon Sep 17 00:00:00 2001 From: Charles Hall Date: Tue, 19 Nov 2024 18:09:14 -0500 Subject: [PATCH] state-res: improve tracing spans and events slight modifications, mainly just restricting these to debug log level to prevent incurring the overhead of the instruments, and tiny adjustments for async state res Co-authored-by: strawberry Signed-off-by: strawberry --- crates/ruma-state-res/src/event_auth.rs | 13 +++++++------ crates/ruma-state-res/src/lib.rs | 23 +++++++++++++++-------- 2 files changed, 22 insertions(+), 14 deletions(-) diff --git a/crates/ruma-state-res/src/event_auth.rs b/crates/ruma-state-res/src/event_auth.rs index 7fec21f3..d6fb59b0 100644 --- a/crates/ruma-state-res/src/event_auth.rs +++ b/crates/ruma-state-res/src/event_auth.rs @@ -18,7 +18,7 @@ use serde::{ Deserialize, }; use serde_json::{from_str as from_json_str, value::RawValue as RawJsonValue}; -use tracing::{debug, error, trace, warn}; +use tracing::{debug, error, instrument, trace, warn}; use crate::{ power_levels::{ @@ -122,6 +122,7 @@ pub fn auth_types_for_event( /// /// The `fetch_state` closure should gather state from a state snapshot. We need to know if the /// event passes auth against some state not a recursive collection of auth_events fields. +#[instrument(level = "debug", skip_all, fields(event_id = incoming_event.event_id().borrow().as_str()))] pub async fn auth_check( room_version: &RoomVersion, incoming_event: &Incoming, @@ -413,14 +414,14 @@ where sender_power_level, ) { if !required_pwr_lvl { - warn!("power level was not allowed"); + warn!("m.room.power_levels was not allowed"); return Ok(false); } } else { - warn!("power level was not allowed"); + warn!("m.room.power_levels was not allowed"); return Ok(false); } - debug!("power levels event allowed"); + debug!("m.room.power_levels event allowed"); } // Room version 3: Redaction events are always accepted (provided the event is allowed by @@ -748,8 +749,8 @@ fn can_send_event(event: impl Event, ple: Option, user_level: Int) - let event_type_power_level = get_send_level(event.event_type(), event.state_key(), ple); debug!( - required_level = %event_type_power_level, - user_level = %user_level, + required_level = i64::from(event_type_power_level), + user_level = i64::from(user_level), state_key = ?event.state_key(), "permissions factors", ); diff --git a/crates/ruma-state-res/src/lib.rs b/crates/ruma-state-res/src/lib.rs index 43402b98..3ec7c3a7 100644 --- a/crates/ruma-state-res/src/lib.rs +++ b/crates/ruma-state-res/src/lib.rs @@ -14,7 +14,7 @@ use ruma_events::{ StateEventType, TimelineEventType, }; use serde_json::from_str as from_json_str; -use tracing::{debug, trace, warn}; +use tracing::{debug, instrument, trace, warn}; mod error; pub mod event_auth; @@ -46,13 +46,14 @@ pub type StateMap = HashMap<(StateEventType, String), T>; /// * `auth_chain_sets` - The full recursive set of `auth_events` for each event in the /// `state_sets`. /// -/// * `fetch_event` - Any event not found in the `event_map` will defer to this closure to find the +/// * `event_fetch` - Any event not found in the `event_map` will defer to this closure to find the /// event. /// /// ## Invariants /// /// The caller of `resolve` must ensure that all the events are from the same room. Although this /// function takes a `RoomId` it does not check that each event is part of the same room. +//#[instrument(level = "debug", skip(state_sets, auth_chain_sets, event_fetch))] pub async fn resolve<'a, E, SetIter, Fetch, FetchFut, Exists, ExistsFut>( room_version: &RoomVersionId, state_sets: impl IntoIterator + Send, @@ -224,6 +225,7 @@ where /// /// The power level is negative because a higher power level is equated to an earlier (further back /// in time) origin server timestamp. +#[instrument(level = "debug", skip_all)] async fn reverse_topological_power_sort( events_to_sort: Vec, auth_diff: &HashSet, @@ -250,7 +252,11 @@ where let mut event_to_pl = HashMap::new(); for event_id in graph.keys() { let pl = get_power_level_for_sender(event_id, fetch_event).await?; - debug!("{event_id} power level {pl}"); + debug!( + event_id = event_id.borrow().as_str(), + power_level = i64::from(pl), + "found the power level of an event's sender", + ); event_to_pl.insert(event_id.clone(), pl); @@ -273,6 +279,7 @@ where /// /// `key_fn` is used as to obtain the power level and age of an event for breaking ties (together /// with the event ID). +#[instrument(level = "debug", skip_all)] pub async fn lexicographical_topological_sort( graph: &HashMap>, key_fn: &F, @@ -451,7 +458,7 @@ where ev, ); } else { - warn!(auth_event_id = %aid, "missing auth event"); + warn!(event_id = aid.borrow().as_str(), "missing auth event"); } } @@ -593,7 +600,7 @@ where E::Id: Borrow + Send, { while let Some(sort_ev) = event { - debug!("mainline event_id {}", sort_ev.event_id()); + debug!(event_id = sort_ev.event_id().borrow().as_str(), "mainline"); let id = sort_ev.event_id(); if let Some(depth) = mainline_map.get(id.borrow()) { return Ok(*depth); @@ -1243,11 +1250,11 @@ mod tests { }; debug!( - "{:#?}", - resolved + resolved = ?resolved .iter() .map(|((ty, key), id)| format!("(({ty}{key:?}), {id})")) - .collect::>() + .collect::>(), + "resolved state", ); let expected =