From 9263d0c94941a20390ee24014bf0e148e45a3078 Mon Sep 17 00:00:00 2001 From: Jonas Platte Date: Sat, 8 May 2021 01:02:42 +0200 Subject: [PATCH] state-res: Switch from log to tracing --- crates/ruma-state-res/Cargo.toml | 4 +- crates/ruma-state-res/src/event_auth.rs | 85 +++++++++---------- crates/ruma-state-res/src/lib.rs | 56 ++++++------ .../ruma-state-res/tests/res_with_auth_ids.rs | 3 +- crates/ruma-state-res/tests/utils.rs | 3 +- 5 files changed, 71 insertions(+), 80 deletions(-) diff --git a/crates/ruma-state-res/Cargo.toml b/crates/ruma-state-res/Cargo.toml index df68d17c..e822505a 100644 --- a/crates/ruma-state-res/Cargo.toml +++ b/crates/ruma-state-res/Cargo.toml @@ -17,15 +17,15 @@ unstable-pre-spec = ["ruma-events/unstable-pre-spec"] [dependencies] itertools = "0.10.0" js_int = "0.2.0" +maplit = "1.0.2" ruma-identifiers = { version = "0.19.0", path = "../ruma-identifiers" } ruma-events = { version = "=0.22.0-alpha.3", path = "../ruma-events" } ruma-serde = { version = "0.3.1", path = "../ruma-serde" } ruma-signatures = { version = "0.7.0", path = "../ruma-signatures" } serde = { version = "1.0.118", features = ["derive"] } serde_json = "1.0.60" -maplit = "1.0.2" thiserror = "1.0.22" -log = "0.4.11" +tracing = "0.1.26" [dev-dependencies] criterion = "0.3.3" diff --git a/crates/ruma-state-res/src/event_auth.rs b/crates/ruma-state-res/src/event_auth.rs index 6a88a1b9..f30699f7 100644 --- a/crates/ruma-state-res/src/event_auth.rs +++ b/crates/ruma-state-res/src/event_auth.rs @@ -1,7 +1,6 @@ use std::{convert::TryFrom, sync::Arc}; use js_int::int; -use log::warn; use maplit::btreeset; use ruma_events::{ room::{ @@ -14,6 +13,7 @@ use ruma_events::{ EventType, }; use ruma_identifiers::{RoomVersionId, UserId}; +use tracing::{debug, info, warn}; use crate::{room_version::RoomVersion, Error, Event, Result, StateMap}; @@ -89,11 +89,7 @@ pub fn auth_check( auth_events: &StateMap>, current_third_party_invite: Option>, ) -> Result { - log::info!( - "auth_check beginning for {} ({})", - incoming_event.event_id(), - incoming_event.kind() - ); + info!("auth_check beginning for {} ({})", incoming_event.event_id(), incoming_event.kind()); // [synapse] check that all the events are in the same room as `incoming_event` @@ -107,17 +103,17 @@ pub fn auth_check( // // 1. If type is m.room.create: if incoming_event.kind() == EventType::RoomCreate { - log::info!("start m.room.create check"); + info!("start m.room.create check"); // If it has any previous events, reject if !incoming_event.prev_events().is_empty() { - log::warn!("the room creation event had previous events"); + warn!("the room creation event had previous events"); return Ok(false); } // If the domain of the room_id does not match the domain of the sender, reject if incoming_event.room_id().server_name() != incoming_event.sender().server_name() { - log::warn!("creation events server does not match sender"); + warn!("creation events server does not match sender"); return Ok(false); // creation events room id does not match senders } @@ -132,17 +128,17 @@ pub fn auth_check( ) .is_err() { - log::warn!("invalid room version found in m.room.create event"); + warn!("invalid room version found in m.room.create event"); return Ok(false); } // If content has no creator field, reject if incoming_event.content().get("creator").is_none() { - log::warn!("no creator field found in room create content"); + warn!("no creator field found in room create content"); return Ok(false); } - log::info!("m.room.create event was allowed"); + info!("m.room.create event was allowed"); return Ok(true); } @@ -162,7 +158,7 @@ pub fn auth_check( for ev_key in auth_events.keys() { // (b) if !expected_auth.contains(ev_key) { - log::warn!("auth_events contained invalid auth event"); + warn!("auth_events contained invalid auth event"); return Ok(false); } } @@ -170,7 +166,7 @@ pub fn auth_check( // 3. If event does not have m.room.create in auth_events reject if auth_events.get(&(EventType::RoomCreate, "".to_string())).is_none() { - log::warn!("no m.room.create event in auth chain"); + warn!("no m.room.create event in auth chain"); return Ok(false); } @@ -179,23 +175,23 @@ pub fn auth_check( // 4. if type is m.room.aliases if incoming_event.kind() == EventType::RoomAliases && room_version.special_case_aliases_auth { - log::info!("starting m.room.aliases check"); + info!("starting m.room.aliases check"); // If sender's domain doesn't matches state_key, reject if incoming_event.state_key() != Some(incoming_event.sender().server_name().to_string()) { - log::warn!("state_key does not match sender"); + warn!("state_key does not match sender"); return Ok(false); } - log::info!("m.room.aliases event was allowed"); + info!("m.room.aliases event was allowed"); return Ok(true); } if incoming_event.kind() == EventType::RoomMember { - log::info!("starting m.room.member check"); + info!("starting m.room.member check"); let state_key = match incoming_event.state_key() { None => { - log::warn!("no statekey in member event"); + warn!("no statekey in member event"); return Ok(false); } Some(s) => s, @@ -207,7 +203,7 @@ pub fn auth_check( .map(|m| serde_json::from_value::(m.clone())); if !matches!(membership, Some(Ok(_))) { - log::warn!("no valid membership field found for m.room.member event content"); + warn!("no valid membership field found for m.room.member event content"); return Ok(false); } @@ -222,7 +218,7 @@ pub fn auth_check( return Ok(false); } - log::info!("m.room.member event was allowed"); + info!("m.room.member event was allowed"); return Ok(true); } @@ -230,11 +226,11 @@ pub fn auth_check( match check_event_sender_in_room(incoming_event.sender(), auth_events) { Some(true) => {} // sender in room Some(false) => { - log::warn!("sender's membership is not join"); + warn!("sender's membership is not join"); return Ok(false); } None => { - log::warn!("sender not found in room"); + warn!("sender not found in room"); return Ok(false); } } @@ -244,32 +240,32 @@ pub fn auth_check( if incoming_event.kind() == EventType::RoomThirdPartyInvite && !can_send_invite(incoming_event, auth_events)? { - log::warn!("sender's cannot send invites in this room"); + warn!("sender's cannot send invites in this room"); return Ok(false); } // If the event type's required power level is greater than the sender's power level, reject // If the event has a state_key that starts with an @ and does not match the sender, reject. if !can_send_event(incoming_event, auth_events) { - log::warn!("user cannot send event"); + warn!("user cannot send event"); return Ok(false); } if incoming_event.kind() == EventType::RoomPowerLevels { - log::info!("starting m.room.power_levels check"); + info!("starting m.room.power_levels check"); if let Some(required_pwr_lvl) = check_power_levels(room_version, incoming_event, auth_events) { if !required_pwr_lvl { - log::warn!("power level was not allowed"); + warn!("power level was not allowed"); return Ok(false); } } else { - log::warn!("power level was not allowed"); + warn!("power level was not allowed"); return Ok(false); } - log::info!("power levels event allowed"); + info!("power levels event allowed"); } // Room version 3: Redaction events are always accepted (provided the event is allowed by @@ -286,7 +282,7 @@ pub fn auth_check( return Ok(false); } - log::info!("allowing event passed all checks"); + info!("allowing event passed all checks"); Ok(true) } @@ -497,12 +493,7 @@ pub fn can_send_event(event: &Arc, auth_events: &StateMap>) let event_type_power_level = get_send_level(&event.kind(), event.state_key(), ple); let user_level = get_user_power_level(event.sender(), auth_events); - log::debug!( - "{} ev_type {} usr {}", - event.event_id().as_str(), - event_type_power_level, - user_level - ); + debug!("{} ev_type {} usr {}", event.event_id().as_str(), event_type_power_level, user_level); if user_level < event_type_power_level { return false; @@ -541,7 +532,7 @@ pub fn check_power_levels( serde_json::from_value::(current_state.content()).unwrap(); // validation of users is done in Ruma, synapse for loops validating user_ids and integers here - log::info!("validation of power event finished"); + info!("validation of power event finished"); let user_level = get_user_power_level(power_event.sender(), auth_events); @@ -553,7 +544,7 @@ pub fn check_power_levels( user_levels_to_check.insert(user); } - log::debug!("users to check {:?}", user_levels_to_check); + debug!("users to check {:?}", user_levels_to_check); let mut event_levels_to_check = btreeset![]; let old_list = ¤t_content.events; @@ -563,7 +554,7 @@ pub fn check_power_levels( event_levels_to_check.insert(ev_id); } - log::debug!("events to check {:?}", event_levels_to_check); + debug!("events to check {:?}", event_levels_to_check); let old_state = ¤t_content; let new_state = &user_content; @@ -581,7 +572,7 @@ pub fn check_power_levels( // If the current value is equal to the sender's current power level, reject if user != power_event.sender() && old_level.map(|int| (*int).into()) == Some(user_level) { - log::warn!("m.room.power_level cannot remove ops == to own"); + warn!("m.room.power_level cannot remove ops == to own"); return Some(false); // cannot remove ops level == to own } @@ -590,7 +581,7 @@ pub fn check_power_levels( let old_level_too_big = old_level.map(|int| (*int).into()) > Some(user_level); let new_level_too_big = new_level.map(|int| (*int).into()) > Some(user_level); if old_level_too_big || new_level_too_big { - log::warn!("m.room.power_level failed to add ops > than own"); + warn!("m.room.power_level failed to add ops > than own"); return Some(false); // cannot add ops greater than own } } @@ -608,7 +599,7 @@ pub fn check_power_levels( let old_level_too_big = old_level.map(|int| (*int).into()) > Some(user_level); let new_level_too_big = new_level.map(|int| (*int).into()) > Some(user_level); if old_level_too_big || new_level_too_big { - log::warn!("m.room.power_level failed to add ops > than own"); + warn!("m.room.power_level failed to add ops > than own"); return Some(false); // cannot add ops greater than own } } @@ -623,7 +614,7 @@ pub fn check_power_levels( let old_level_too_big = i64::from(old_level) > user_level; let new_level_too_big = i64::from(new_level) > user_level; if old_level_too_big || new_level_too_big { - log::warn!("m.room.power_level failed to add ops > than own"); + warn!("m.room.power_level failed to add ops > than own"); return Some(false); // cannot add ops greater than own } } @@ -639,7 +630,7 @@ pub fn check_power_levels( let new_level_too_big = new_lvl > user_level; if old_level_too_big || new_level_too_big { - log::warn!("cannot add ops > than own"); + warn!("cannot add ops > than own"); return Some(false); } } @@ -669,7 +660,7 @@ pub fn check_redaction( let redact_level = get_named_level(auth_events, "redact", 50); if user_level >= redact_level { - log::info!("redaction allowed via power levels"); + info!("redaction allowed via power levels"); return Ok(true); } @@ -678,7 +669,7 @@ pub fn check_redaction( if redaction_event.event_id().server_name() == redaction_event.redacts().as_ref().and_then(|id| id.server_name()) { - log::info!("redaction event allowed via room version 1 rules"); + info!("redaction event allowed via room version 1 rules"); return Ok(true); } @@ -773,7 +764,7 @@ pub fn get_send_level( state_key: Option, power_lvl: Option<&Arc>, ) -> i64 { - log::debug!("{:?} {:?}", e_type, state_key); + debug!("{:?} {:?}", e_type, state_key); power_lvl .and_then(|ple| { serde_json::from_value::(ple.content()) diff --git a/crates/ruma-state-res/src/lib.rs b/crates/ruma-state-res/src/lib.rs index ce21514c..240e3de7 100644 --- a/crates/ruma-state-res/src/lib.rs +++ b/crates/ruma-state-res/src/lib.rs @@ -15,6 +15,7 @@ use ruma_events::{ EventType, }; use ruma_identifiers::{EventId, RoomId, RoomVersionId}; +use tracing::{debug, info, warn}; mod error; pub mod event_auth; @@ -55,31 +56,31 @@ impl StateResolution { auth_events: Vec>, event_map: &mut EventMap>, ) -> Result> { - log::info!("State resolution starting"); + info!("State resolution starting"); // split non-conflicting and conflicting state let (clean, conflicting) = StateResolution::separate(state_sets); - log::info!("non conflicting {:?}", clean.len()); + info!("non conflicting {:?}", clean.len()); if conflicting.is_empty() { - log::info!("no conflicting state found"); + info!("no conflicting state found"); return Ok(clean); } - log::info!("{} conflicting events", conflicting.len()); + info!("{} conflicting events", conflicting.len()); // the set of auth events that are not common across server forks let mut auth_diff = StateResolution::get_auth_chain_diff(room_id, &auth_events)?; - log::debug!("auth diff size {:?}", auth_diff); + debug!("auth diff size {:?}", auth_diff); // add the auth_diff to conflicting now we have a full set of conflicting events auth_diff.extend(conflicting.values().cloned().flatten()); let mut all_conflicted = auth_diff.into_iter().collect::>().into_iter().collect::>(); - log::info!("full conflicted set is {} events", all_conflicted.len()); + info!("full conflicted set is {} events", all_conflicted.len()); // we used to check that all events are events from the correct room // this is now a check the caller of `resolve` must make. @@ -104,7 +105,7 @@ impl StateResolution { &all_conflicted, ); - log::debug!("SRTD {:?}", sorted_control_levels); + debug!("SRTD {:?}", sorted_control_levels); let room_version = RoomVersion::new(room_version)?; // sequentially auth check each control event. @@ -116,7 +117,7 @@ impl StateResolution { event_map, )?; - log::debug!( + debug!( "AUTHED {:?}", resolved_control.iter().map(|(key, id)| (key, id.to_string())).collect::>() ); @@ -134,20 +135,17 @@ impl StateResolution { .cloned() .collect::>(); - log::debug!( - "LEFT {:?}", - events_to_resolve.iter().map(ToString::to_string).collect::>() - ); + debug!("LEFT {:?}", events_to_resolve.iter().map(ToString::to_string).collect::>()); // This "epochs" power level event let power_event = resolved_control.get(&(EventType::RoomPowerLevels, "".into())); - log::debug!("PL {:?}", power_event); + debug!("PL {:?}", power_event); let sorted_left_events = StateResolution::mainline_sort(room_id, &events_to_resolve, power_event, event_map); - log::debug!( + debug!( "SORTED LEFT {:?}", sorted_left_events.iter().map(ToString::to_string).collect::>() ); @@ -177,7 +175,7 @@ impl StateResolution { ) -> (StateMap, StateMap>) { use itertools::Itertools; - log::info!("seperating {} sets of events into conflicted/unconflicted", state_sets.len()); + info!("seperating {} sets of events into conflicted/unconflicted", state_sets.len()); let mut unconflicted_state = StateMap::new(); let mut conflicted_state = StateMap::new(); @@ -242,7 +240,7 @@ impl StateResolution { event_map: &mut EventMap>, auth_diff: &[EventId], ) -> Vec { - log::debug!("reverse topological sort of power events"); + debug!("reverse topological sort of power events"); let mut graph = BTreeMap::new(); for event_id in events_to_sort.iter() { @@ -259,7 +257,7 @@ impl StateResolution { let mut event_to_pl = BTreeMap::new(); for event_id in graph.keys() { let pl = StateResolution::get_power_level_for_sender(room_id, event_id, event_map); - log::info!("{} power level {}", event_id.to_string(), pl); + info!("{} power level {}", event_id.to_string(), pl); event_to_pl.insert(event_id.clone(), pl); @@ -269,11 +267,11 @@ impl StateResolution { } StateResolution::lexicographical_topological_sort(&graph, |event_id| { - // log::debug!("{:?}", event_map.get(event_id).unwrap().origin_server_ts()); + // debug!("{:?}", event_map.get(event_id).unwrap().origin_server_ts()); let ev = event_map.get(event_id).unwrap(); let pl = event_to_pl.get(event_id).unwrap(); - log::debug!("{:?}", (-*pl, ev.origin_server_ts(), &ev.event_id())); + debug!("{:?}", (-*pl, ev.origin_server_ts(), &ev.event_id())); // This return value is the key used for sorting events, // events are then sorted by power level, time, @@ -292,7 +290,7 @@ impl StateResolution { where F: Fn(&EventId) -> (i64, SystemTime, EventId), { - log::info!("starting lexicographical topological sort"); + info!("starting lexicographical topological sort"); // NOTE: an event that has no incoming edges happened most recently, // and an event that has no outgoing edges happened least recently. @@ -356,7 +354,7 @@ impl StateResolution { event_id: &EventId, event_map: &mut EventMap>, ) -> i64 { - log::info!("fetch event ({}) senders power level", event_id.to_string()); + info!("fetch event ({}) senders power level", event_id.to_string()); let event = StateResolution::get_or_load_event(room_id, event_id, event_map); let mut pl = None; @@ -381,7 +379,7 @@ impl StateResolution { { if let Ok(ev) = event { if let Some(user) = content.users.get(ev.sender()) { - log::debug!("found {} at power_level {}", ev.sender().as_str(), user); + debug!("found {} at power_level {}", ev.sender().as_str(), user); return (*user).into(); } } @@ -408,9 +406,9 @@ impl StateResolution { unconflicted_state: &StateMap, event_map: &mut EventMap>, ) -> Result> { - log::info!("starting iterative auth check"); + info!("starting iterative auth check"); - log::debug!( + debug!( "performing auth checks on {:?}", events_to_check.iter().map(ToString::to_string).collect::>() ); @@ -438,7 +436,7 @@ impl StateResolution { ev, ); } else { - log::warn!("auth event id for {} is missing {}", aid, event_id); + warn!("auth event id for {} is missing {}", aid, event_id); } } @@ -457,7 +455,7 @@ impl StateResolution { } } - log::debug!("event to check {:?}", event.event_id().as_str()); + debug!("event to check {:?}", event.event_id().as_str()); let most_recent_prev_event = event .prev_events() @@ -486,7 +484,7 @@ impl StateResolution { resolved_state.insert((event.kind(), state_key), event_id.clone()); } else { // synapse passes here on AuthError. We do not add this event to resolved_state. - log::warn!("event {} failed the authentication check", event_id.to_string()); + warn!("event {} failed the authentication check", event_id.to_string()); } // TODO: if these functions are ever made async here @@ -509,7 +507,7 @@ impl StateResolution { resolved_power_level: Option<&EventId>, event_map: &mut EventMap>, ) -> Vec { - log::debug!("mainline sort of events"); + debug!("mainline sort of events"); // There are no EventId's to sort, bail. if to_sort.is_empty() { @@ -585,7 +583,7 @@ impl StateResolution { event_map: &mut EventMap>, ) -> Result { while let Some(sort_ev) = event { - log::debug!("mainline event_id {}", sort_ev.event_id().to_string()); + debug!("mainline event_id {}", sort_ev.event_id().to_string()); let id = &sort_ev.event_id(); if let Some(depth) = mainline_map.get(id) { return Ok(*depth); diff --git a/crates/ruma-state-res/tests/res_with_auth_ids.rs b/crates/ruma-state-res/tests/res_with_auth_ids.rs index 6ed202c0..62adbff5 100644 --- a/crates/ruma-state-res/tests/res_with_auth_ids.rs +++ b/crates/ruma-state-res/tests/res_with_auth_ids.rs @@ -6,6 +6,7 @@ use ruma_events::EventType; use ruma_identifiers::{EventId, RoomVersionId}; use ruma_state_res::{EventMap, StateMap, StateResolution}; use serde_json::json; +use tracing::debug; mod utils; use utils::{ @@ -82,7 +83,7 @@ fn ban_with_auth_chains2() { Err(e) => panic!("{}", e), }; - log::debug!( + debug!( "{:#?}", resolved .iter() diff --git a/crates/ruma-state-res/tests/utils.rs b/crates/ruma-state-res/tests/utils.rs index 3342279d..e7868ea3 100644 --- a/crates/ruma-state-res/tests/utils.rs +++ b/crates/ruma-state-res/tests/utils.rs @@ -20,6 +20,7 @@ use ruma_events::{ use ruma_identifiers::{EventId, RoomId, RoomVersionId, UserId}; use ruma_state_res::{auth_types_for_event, Error, Event, Result, StateMap, StateResolution}; use serde_json::{json, Value as JsonValue}; +use tracing::info; use tracing_subscriber as tracer; pub use event::StateEvent; @@ -95,7 +96,7 @@ pub fn do_check( .cloned() .collect::>(); - log::info!( + info!( "{:#?}", state_sets .iter()