chris/ruwuma
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

state-res: Switch from log to tracing

Browse Source
This commit is contained in:
Jonas Platte 2021-05-08 01:02:42 +02:00
parent 410b4aed25
commit 9263d0c949
No known key found for this signature in database
GPG Key ID: 7D261D771D915378
5 changed files with 71 additions and 80 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
crates/ruma-state-res/Cargo.toml
View File

@ -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"

85
crates/ruma-state-res/src/event_auth.rs
View File

@ -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<E: Event>(
auth_events: &StateMap<Arc<E>>,
current_third_party_invite: Option<Arc<E>>,
) -> Result<bool> {
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<E: Event>(
//
// 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<E: Event>(
)
.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<E: Event>(
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<E: Event>(
// 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<E: Event>(
// 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<E: Event>(
.map(|m| serde_json::from_value::<MembershipState>(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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(event: &Arc<E>, auth_events: &StateMap<Arc<E>>)
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<E: Event>(
serde_json::from_value::<PowerLevelsEventContent>(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<E: Event>(
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 = &current_content.events;
@ -563,7 +554,7 @@ pub fn check_power_levels<E: Event>(
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 = &current_content;
let new_state = &user_content;
@ -581,7 +572,7 @@ pub fn check_power_levels<E: Event>(
// 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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(
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<E: Event>(
state_key: Option<String>,
power_lvl: Option<&Arc<E>>,
) -> i64 {
log::debug!("{:?} {:?}", e_type, state_key);
debug!("{:?} {:?}", e_type, state_key);
power_lvl
.and_then(|ple| {
serde_json::from_value::<PowerLevelsEventContent>(ple.content())

56
crates/ruma-state-res/src/lib.rs
View File

@ -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<Vec<EventId>>,
event_map: &mut EventMap<Arc<E>>,
) -> Result<StateMap<EventId>> {
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::<BTreeSet<_>>().into_iter().collect::<Vec<_>>();
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::<Vec<_>>()
);
@ -134,20 +135,17 @@ impl StateResolution {
.cloned()
.collect::<Vec<_>>();
log::debug!(
"LEFT {:?}",
events_to_resolve.iter().map(ToString::to_string).collect::<Vec<_>>()
);
debug!("LEFT {:?}", events_to_resolve.iter().map(ToString::to_string).collect::<Vec<_>>());
// 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::<Vec<_>>()
);
@ -177,7 +175,7 @@ impl StateResolution {
) -> (StateMap<EventId>, StateMap<Vec<EventId>>) {
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<Arc<E>>,
auth_diff: &[EventId],
) -> Vec<EventId> {
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<Arc<E>>,
) -> 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<EventId>,
event_map: &mut EventMap<Arc<E>>,
) -> Result<StateMap<EventId>> {
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::<Vec<_>>()
);
@ -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<Arc<E>>,
) -> Vec<EventId> {
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<Arc<E>>,
) -> Result<usize> {
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);

3
crates/ruma-state-res/tests/res_with_auth_ids.rs
View File

@ -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()

3
crates/ruma-state-res/tests/utils.rs
View File

@ -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::<Vec<_>>();
log::info!(
info!(
"{:#?}",
state_sets
.iter()