From c3fb396352196bb3803b95caba7caebbe62f2785 Mon Sep 17 00:00:00 2001 From: Charles Hall Date: Thu, 7 Nov 2024 18:52:02 -0500 Subject: [PATCH] state-res: improve tracing spans and events * Make use of tracing's structured logging features * Change some wording to align with the spec --- crates/ruma-state-res/src/event_auth.rs | 15 +++++++---- crates/ruma-state-res/src/lib.rs | 35 ++++++++++++++----------- 2 files changed, 29 insertions(+), 21 deletions(-) diff --git a/crates/ruma-state-res/src/event_auth.rs b/crates/ruma-state-res/src/event_auth.rs index 4132c421..720c9f07 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, warn}; +use tracing::{debug, trace, error, warn}; use crate::{ power_levels::{ @@ -747,7 +747,12 @@ fn valid_membership_change( fn can_send_event(event: impl Event, ple: Option, user_level: Int) -> bool { let event_type_power_level = get_send_level(event.event_type(), event.state_key(), ple); - debug!("{} ev_type {event_type_power_level} usr {user_level}", event.event_id()); + debug!( + required_level = %event_type_power_level, + user_level = %user_level, + state_key = ?event.state_key(), + "permissions factors", + ); if user_level < event_type_power_level { return false; @@ -772,7 +777,7 @@ fn check_power_levels( match power_event.state_key() { Some("") => {} Some(key) => { - error!("m.room.power_levels event has non-empty state key: {key}"); + error!(state_key = key, "m.room.power_levels event has non-empty state key"); return None; } None => { @@ -810,7 +815,7 @@ fn check_power_levels( user_levels_to_check.insert(user); } - debug!("users to check {user_levels_to_check:?}"); + trace!(set = ?user_levels_to_check, "user levels to check"); let mut event_levels_to_check = BTreeSet::new(); let old_list = ¤t_content.events; @@ -819,7 +824,7 @@ fn check_power_levels( event_levels_to_check.insert(ev_id); } - debug!("events to check {event_levels_to_check:?}"); + trace!(set = ?event_levels_to_check, "event levels to check"); let old_state = ¤t_content; let new_state = &user_content; diff --git a/crates/ruma-state-res/src/lib.rs b/crates/ruma-state-res/src/lib.rs index ea3b4bd5..43402b98 100644 --- a/crates/ruma-state-res/src/lib.rs +++ b/crates/ruma-state-res/src/lib.rs @@ -75,16 +75,16 @@ where // Split non-conflicting and conflicting state let (clean, conflicting) = separate(state_sets.into_iter()); - debug!("non conflicting events: {}", clean.len()); - trace!("{clean:?}"); + debug!(count = clean.len(), "non-conflicting events"); + trace!(map = ?clean, "non-conflicting events"); if conflicting.is_empty() { debug!("no conflicting state found"); return Ok(clean); } - debug!("conflicting events: {}", conflicting.len()); - debug!("{conflicting:?}"); + debug!(count = conflicting.len(), "conflicting events"); + trace!(map = ?conflicting, "conflicting events"); let auth_chain_diff = get_auth_chain_diff(&auth_chain_sets).chain(conflicting.into_values().flatten()); @@ -97,8 +97,8 @@ where .collect() .await; - debug!("full conflicted set: {}", all_conflicted.len()); - debug!("{all_conflicted:?}"); + debug!(count = all_conflicted.len(), "full conflicted set"); + trace!(set = ?all_conflicted, "full conflicted set"); // We used to check that all events are events from the correct room // this is now a check the caller of `resolve` must make. @@ -114,8 +114,8 @@ where let sorted_control_levels = reverse_topological_power_sort(control_events, &all_conflicted, &event_fetch).await?; - debug!("sorted control events: {}", sorted_control_levels.len()); - trace!("{sorted_control_levels:?}"); + debug!(count = sorted_control_levels.len(), "power events"); + trace!(list = ?sorted_control_levels, "sorted power events"); let room_version = RoomVersion::new(room_version)?; // Sequentially auth check each control event. @@ -123,8 +123,8 @@ where iterative_auth_check(&room_version, &sorted_control_levels, clean.clone(), &event_fetch) .await?; - debug!("resolved control events: {}", resolved_control.len()); - trace!("{resolved_control:?}"); + debug!(count = resolved_control.len(), "resolved power events"); + trace!(map = ?resolved_control, "resolved power events"); // At this point the control_events have been resolved we now have to // sort the remaining events using the mainline of the resolved power level. @@ -138,18 +138,18 @@ where .cloned() .collect::>(); - debug!("events left to resolve: {}", events_to_resolve.len()); - trace!("{events_to_resolve:?}"); + debug!(count = events_to_resolve.len(), "events left to resolve"); + trace!(list = ?events_to_resolve, "events left to resolve"); // This "epochs" power level event let power_event = resolved_control.get(&(StateEventType::RoomPowerLevels, "".into())); - debug!("power event: {power_event:?}"); + debug!(event_id = ?power_event, "power event"); let sorted_left_events = mainline_sort(&events_to_resolve, power_event.cloned(), &event_fetch).await?; - trace!("events left, sorted: {sorted_left_events:?}"); + trace!(list = ?sorted_left_events, "events left, sorted"); let mut resolved_state = iterative_auth_check( &room_version, @@ -162,6 +162,9 @@ where // Add unconflicted state to the resolved state // We priorities the unconflicting state resolved_state.extend(clean); + + debug!("state resolution finished"); + Ok(resolved_state) } @@ -424,7 +427,7 @@ where { debug!("starting iterative auth check"); - debug!("performing auth checks on {events_to_check:?}"); + trace!(list = ?events_to_check, "events to check"); let mut resolved_state = unconflicted_state; @@ -448,7 +451,7 @@ where ev, ); } else { - warn!("auth event id for {aid} is missing {event_id}"); + warn!(auth_event_id = %aid, "missing auth event"); } }