diff --git a/Cargo.toml b/Cargo.toml index ff091cf2..23c7ba51 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,9 +15,9 @@ repository = "https://github.com/ruma/state-res" itertools = "0.10.0" serde = { version = "1.0.118", features = ["derive"] } serde_json = "1.0.60" -tracing = "0.1.22" maplit = "1.0.2" thiserror = "1.0.22" +log = "0.4.11" [dependencies.ruma] git = "https://github.com/ruma/ruma" diff --git a/src/event_auth.rs b/src/event_auth.rs index 5b8e5e76..6c8ed951 100644 --- a/src/event_auth.rs +++ b/src/event_auth.rs @@ -80,7 +80,7 @@ pub fn auth_check( auth_events: &StateMap>, current_third_party_invite: Option>, ) -> Result { - tracing::info!("auth_check beginning for {}", incoming_event.kind()); + log::info!("auth_check beginning for {}", incoming_event.kind()); // [synapse] check that all the events are in the same room as `incoming_event` @@ -94,17 +94,17 @@ pub fn auth_check( // // 1. If type is m.room.create: if incoming_event.kind() == EventType::RoomCreate { - tracing::info!("start m.room.create check"); + log::info!("start m.room.create check"); // If it has any previous events, reject if !incoming_event.prev_events().is_empty() { - tracing::warn!("the room creation event had previous events"); + log::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() { - tracing::warn!("creation events server does not match sender"); + log::warn!("creation events server does not match sender"); return Ok(false); // creation events room id does not match senders } @@ -119,17 +119,17 @@ pub fn auth_check( ) .is_err() { - tracing::warn!("invalid room version found in m.room.create event"); + log::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() { - tracing::warn!("no creator field found in room create content"); + log::warn!("no creator field found in room create content"); return Ok(false); } - tracing::info!("m.room.create event was allowed"); + log::info!("m.room.create event was allowed"); return Ok(true); } @@ -149,7 +149,7 @@ pub fn auth_check( for ev_key in auth_events.keys() { // (b) if !expected_auth.contains(ev_key) { - tracing::warn!("auth_events contained invalid auth event"); + log::warn!("auth_events contained invalid auth event"); return Ok(false); } } @@ -160,7 +160,7 @@ pub fn auth_check( .get(&(EventType::RoomCreate, Some("".into()))) .is_none() { - tracing::warn!("no m.room.create event in auth chain"); + log::warn!("no m.room.create event in auth chain"); return Ok(false); } @@ -169,32 +169,32 @@ pub fn auth_check( // 4. if type is m.room.aliases if incoming_event.kind() == EventType::RoomAliases { - tracing::info!("starting m.room.aliases check"); + log::info!("starting m.room.aliases check"); // [synapse] adds `&& room_version` "special case aliases auth" // [synapse] // if event.state_key.unwrap().is_empty() { - // tracing::warn!("state_key must be non-empty"); + // log::warn!("state_key must be non-empty"); // return Ok(false); // and be non-empty state_key (point to a user_id) // } // If sender's domain doesn't matches state_key, reject if incoming_event.state_key() != Some(incoming_event.sender().server_name().to_string()) { - tracing::warn!("state_key does not match sender"); + log::warn!("state_key does not match sender"); return Ok(false); } - tracing::info!("m.room.aliases event was allowed"); + log::info!("m.room.aliases event was allowed"); return Ok(true); } if incoming_event.kind() == EventType::RoomMember { - tracing::info!("starting m.room.member check"); + log::info!("starting m.room.member check"); if serde_json::from_value::(incoming_event.content()) .is_err() { - tracing::warn!("no membership filed found for m.room.member event content"); + log::warn!("no membership filed found for m.room.member event content"); return Ok(false); } @@ -209,7 +209,7 @@ pub fn auth_check( return Ok(false); } - tracing::info!("m.room.member event was allowed"); + log::info!("m.room.member event was allowed"); return Ok(true); } @@ -217,11 +217,11 @@ pub fn auth_check( match check_event_sender_in_room(&incoming_event.sender(), &auth_events) { Some(true) => {} // sender in room Some(false) => { - tracing::warn!("sender's membership is not join"); + log::warn!("sender's membership is not join"); return Ok(false); } None => { - tracing::warn!("sender not found in room"); + log::warn!("sender not found in room"); return Ok(false); } } @@ -231,32 +231,32 @@ pub fn auth_check( if incoming_event.kind() == EventType::RoomThirdPartyInvite && !can_send_invite(incoming_event, &auth_events)? { - tracing::warn!("sender's cannot send invites in this room"); + log::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) { - tracing::warn!("user cannot send event"); + log::warn!("user cannot send event"); return Ok(false); } if incoming_event.kind() == EventType::RoomPowerLevels { - tracing::info!("starting m.room.power_levels check"); + log::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 { - tracing::warn!("power level was not allowed"); + log::warn!("power level was not allowed"); return Ok(false); } } else { - tracing::warn!("power level was not allowed"); + log::warn!("power level was not allowed"); return Ok(false); } - tracing::info!("power levels event allowed"); + log::info!("power levels event allowed"); } if incoming_event.kind() == EventType::RoomRedaction @@ -265,7 +265,7 @@ pub fn auth_check( return Ok(false); } - tracing::info!("allowing event passed all checks"); + log::info!("allowing event passed all checks"); Ok(true) } @@ -447,7 +447,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); - tracing::debug!( + log::debug!( "{} ev_type {} usr {}", event.event_id().as_str(), event_type_power_level, @@ -496,7 +496,7 @@ pub fn check_power_levels( .unwrap(); // validation of users is done in Ruma, synapse for loops validating user_ids and integers here - tracing::info!("validation of power event finished"); + log::info!("validation of power event finished"); let user_level = get_user_power_level(&power_event.sender(), auth_events); @@ -508,7 +508,7 @@ pub fn check_power_levels( user_levels_to_check.insert(user); } - tracing::debug!("users to check {:?}", user_levels_to_check); + log::debug!("users to check {:?}", user_levels_to_check); let mut event_levels_to_check = btreeset![]; let old_list = ¤t_content.events; @@ -518,7 +518,7 @@ pub fn check_power_levels( event_levels_to_check.insert(ev_id); } - tracing::debug!("events to check {:?}", event_levels_to_check); + log::debug!("events to check {:?}", event_levels_to_check); // [synapse] validate MSC2209 depending on room version check "notifications". // if RoomVersion::new(room_version).limit_notifications_power_levels { @@ -528,7 +528,7 @@ pub fn check_power_levels( // let old_level_too_big = old_level > user_level; // let new_level_too_big = new_level > user_level; // if old_level_too_big || new_level_too_big { - // tracing::warn!("m.room.power_level cannot add ops > than own"); + // log::warn!("m.room.power_level cannot add ops > than own"); // return Some(false); // cannot add ops greater than own // } // } @@ -549,7 +549,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) { - tracing::warn!("m.room.power_level cannot remove ops == to own"); + log::warn!("m.room.power_level cannot remove ops == to own"); return Some(false); // cannot remove ops level == to own } @@ -558,7 +558,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 { - tracing::warn!("m.room.power_level failed to add ops > than own"); + log::warn!("m.room.power_level failed to add ops > than own"); return Some(false); // cannot add ops greater than own } } @@ -576,7 +576,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 { - tracing::warn!("m.room.power_level failed to add ops > than own"); + log::warn!("m.room.power_level failed to add ops > than own"); return Some(false); // cannot add ops greater than own } } @@ -598,7 +598,7 @@ pub fn check_power_levels( let new_level_too_big = new_lvl > user_level; if old_level_too_big || new_level_too_big { - tracing::warn!("cannot add ops > than own"); + log::warn!("cannot add ops > than own"); return Some(false); } } @@ -628,7 +628,7 @@ pub fn check_redaction( let redact_level = get_named_level(auth_events, "redact", 50); if user_level >= redact_level { - tracing::info!("redaction allowed via power levels"); + log::info!("redaction allowed via power levels"); return Ok(true); } @@ -648,7 +648,7 @@ pub fn check_redaction( .as_ref() .and_then(|id| id.server_name()) { - tracing::info!("redaction event allowed via room version 1 rules"); + log::info!("redaction event allowed via room version 1 rules"); return Ok(true); } } @@ -746,7 +746,7 @@ pub fn get_send_level( state_key: Option, power_lvl: Option<&Arc>, ) -> i64 { - tracing::debug!("{:?} {:?}", e_type, state_key); + log::debug!("{:?} {:?}", e_type, state_key); if let Some(ple) = power_lvl { if let Ok(content) = serde_json::from_value::(ple.content()) diff --git a/src/lib.rs b/src/lib.rs index 7bd58549..99080d75 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -48,7 +48,7 @@ impl StateResolution { current_state: &StateMap, event_map: &EventMap>, ) -> Result { - tracing::info!("Applying a single event, state resolution starting"); + log::info!("Applying a single event, state resolution starting"); let ev = incoming_event; let prev_event = if let Some(id) = ev.prev_events().first() { @@ -91,24 +91,24 @@ impl StateResolution { auth_events: Vec>, event_map: &mut EventMap>, ) -> Result> { - tracing::info!("State resolution starting"); + log::info!("State resolution starting"); // split non-conflicting and conflicting state let (clean, conflicting) = StateResolution::separate(&state_sets); - tracing::info!("non conflicting {:?}", clean.len()); + log::info!("non conflicting {:?}", clean.len()); if conflicting.is_empty() { - tracing::info!("no conflicting state found"); + log::info!("no conflicting state found"); return Ok(clean); } - tracing::info!("{} conflicting events", conflicting.len()); + log::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)?; - tracing::debug!("auth diff size {:?}", auth_diff); + log::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()); @@ -118,7 +118,7 @@ impl StateResolution { .into_iter() .collect::>(); - tracing::info!("full conflicted set is {} events", all_conflicted.len()); + log::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. @@ -143,7 +143,7 @@ impl StateResolution { &all_conflicted, ); - tracing::debug!("SRTD {:?}", sorted_control_levels); + log::debug!("SRTD {:?}", sorted_control_levels); // sequentially auth check each control event. let resolved_control = StateResolution::iterative_auth_check( @@ -154,7 +154,7 @@ impl StateResolution { event_map, )?; - tracing::debug!( + log::debug!( "AUTHED {:?}", resolved_control .iter() @@ -174,7 +174,7 @@ impl StateResolution { .cloned() .collect::>(); - tracing::debug!( + log::debug!( "LEFT {:?}", events_to_resolve .iter() @@ -185,12 +185,12 @@ impl StateResolution { // This "epochs" power level event let power_event = resolved_control.get(&(EventType::RoomPowerLevels, Some("".into()))); - tracing::debug!("PL {:?}", power_event); + log::debug!("PL {:?}", power_event); let sorted_left_events = StateResolution::mainline_sort(room_id, &events_to_resolve, power_event, event_map); - tracing::debug!( + log::debug!( "SORTED LEFT {:?}", sorted_left_events .iter() @@ -223,7 +223,7 @@ impl StateResolution { ) -> (StateMap, StateMap>) { use itertools::Itertools; - tracing::info!( + log::info!( "seperating {} sets of events into conflicted/unconflicted", state_sets.len() ); @@ -299,7 +299,7 @@ impl StateResolution { event_map: &mut EventMap>, auth_diff: &[EventId], ) -> Vec { - tracing::debug!("reverse topological sort of power events"); + log::debug!("reverse topological sort of power events"); let mut graph = BTreeMap::new(); for (idx, event_id) in events_to_sort.iter().enumerate() { @@ -318,7 +318,7 @@ impl StateResolution { let mut event_to_pl = BTreeMap::new(); for (idx, event_id) in graph.keys().enumerate() { let pl = StateResolution::get_power_level_for_sender(room_id, &event_id, event_map); - tracing::info!("{} power level {}", event_id.to_string(), pl); + log::info!("{} power level {}", event_id.to_string(), pl); event_to_pl.insert(event_id.clone(), pl); @@ -330,11 +330,11 @@ impl StateResolution { } StateResolution::lexicographical_topological_sort(&graph, |event_id| { - // tracing::debug!("{:?}", event_map.get(event_id).unwrap().origin_server_ts()); + // log::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(); - tracing::debug!("{:?}", (-*pl, ev.origin_server_ts(), &ev.event_id())); + log::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, @@ -353,7 +353,7 @@ impl StateResolution { where F: Fn(&EventId) -> (i64, SystemTime, EventId), { - tracing::info!("starting lexicographical topological sort"); + log::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. @@ -422,7 +422,7 @@ impl StateResolution { event_id: &EventId, event_map: &mut EventMap>, ) -> i64 { - tracing::info!("fetch event ({}) senders power level", event_id.to_string()); + log::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; @@ -457,7 +457,7 @@ impl StateResolution { { if let Ok(ev) = event { if let Some(user) = content.users.get(&ev.sender()) { - tracing::debug!("found {} at power_level {}", ev.sender().as_str(), user); + log::debug!("found {} at power_level {}", ev.sender().as_str(), user); return (*user).into(); } } @@ -484,9 +484,9 @@ impl StateResolution { unconflicted_state: &StateMap, event_map: &mut EventMap>, ) -> Result> { - tracing::info!("starting iterative auth check"); + log::info!("starting iterative auth check"); - tracing::debug!( + log::debug!( "performing auth checks on {:?}", events_to_check .iter() @@ -505,7 +505,7 @@ impl StateResolution { // TODO synapse check "rejected_reason", I'm guessing this is redacted_because in ruma ?? auth_events.insert((ev.kind(), ev.state_key()), ev); } else { - tracing::warn!("auth event id for {} is missing {}", aid, event_id); + log::warn!("auth event id for {} is missing {}", aid, event_id); } } @@ -524,7 +524,7 @@ impl StateResolution { } } - tracing::debug!("event to check {:?}", event.event_id().as_str()); + log::debug!("event to check {:?}", event.event_id().as_str()); let most_recent_prev_event = event .prev_events() @@ -553,7 +553,7 @@ impl StateResolution { resolved_state.insert((event.kind(), event.state_key()), event_id.clone()); } else { // synapse passes here on AuthError. We do not add this event to resolved_state. - tracing::warn!( + log::warn!( "event {} failed the authentication check", event_id.to_string() ); @@ -581,7 +581,7 @@ impl StateResolution { resolved_power_level: Option<&EventId>, event_map: &mut EventMap>, ) -> Vec { - tracing::debug!("mainline sort of events"); + log::debug!("mainline sort of events"); // There are no EventId's to sort, bail. if to_sort.is_empty() { @@ -663,7 +663,7 @@ impl StateResolution { event_map: &mut EventMap>, ) -> Result { while let Some(sort_ev) = event { - tracing::debug!("mainline event_id {}", sort_ev.event_id().to_string()); + log::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/tests/res_with_auth_ids.rs b/tests/res_with_auth_ids.rs index 169714e4..de99ac4e 100644 --- a/tests/res_with_auth_ids.rs +++ b/tests/res_with_auth_ids.rs @@ -91,7 +91,7 @@ fn ban_with_auth_chains2() { Err(e) => panic!("{}", e), }; - tracing::debug!( + log::debug!( "{:#?}", resolved .iter() diff --git a/tests/utils.rs b/tests/utils.rs index c3570ea6..7423eb0e 100644 --- a/tests/utils.rs +++ b/tests/utils.rs @@ -99,7 +99,7 @@ pub fn do_check( .cloned() .collect::>(); - tracing::info!( + log::info!( "{:#?}", state_sets .iter()