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

Clean up logging calls

Browse Source
This commit is contained in:
Devin Ragotzy 2020-07-27 17:10:06 -04:00
parent 4990dac5fe
commit 77cbcc7ee2
3 changed files with 45 additions and 75 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

70
src/event_auth.rs
View File

@ -68,12 +68,15 @@ pub fn auth_check(
auth_events: StateMap<StateEvent>, auth_events: StateMap<StateEvent>,
do_sig_check: bool, do_sig_check: bool,
) -> Option<bool> { ) -> Option<bool> {
tracing::info!("auth_check beginning"); tracing::info!(
"auth_check beginning for {}",
event.event_id().unwrap().as_str()
);
// don't let power from other rooms be used // don't let power from other rooms be used
for auth_event in auth_events.values() { for auth_event in auth_events.values() {
if auth_event.room_id() != event.room_id() { if auth_event.room_id() != event.room_id() {
tracing::info!("found auth event that did not match event's room_id"); tracing::warn!("found auth event that did not match event's room_id");
return Some(false); return Some(false);
} }
} }
@ -91,7 +94,7 @@ pub fn auth_check(
}; };
if event.signatures().get(sender_domain).is_none() && !is_invite_via_3pid { if event.signatures().get(sender_domain).is_none() && !is_invite_via_3pid {
tracing::info!("event not signed by sender's server"); tracing::warn!("event not signed by sender's server");
return Some(false); return Some(false);
} }
} }
@ -108,7 +111,7 @@ pub fn auth_check(
// domain of room_id must match domain of sender. // domain of room_id must match domain of sender.
if event.room_id().map(|id| id.server_name()) != Some(event.sender().server_name()) { if event.room_id().map(|id| id.server_name()) != Some(event.sender().server_name()) {
tracing::info!("creation events server does not match sender"); tracing::warn!("creation events server does not match sender");
return Some(false); // creation events room id does not match senders return Some(false); // creation events room id does not match senders
} }
@ -124,6 +127,7 @@ pub fn auth_check(
) )
.is_err() .is_err()
{ {
tracing::warn!("invalid room version found in m.room.create event");
return Some(false); return Some(false);
} }
@ -157,13 +161,16 @@ pub fn auth_check(
tracing::info!("starting m.room.aliases check"); tracing::info!("starting m.room.aliases check");
// TODO && room_version "special case aliases auth" ?? // TODO && room_version "special case aliases auth" ??
if event.state_key().is_none() { if event.state_key().is_none() {
tracing::warn!("no state_key field found for event");
return Some(false); // must have state_key return Some(false); // must have state_key
} }
if event.state_key().unwrap().is_empty() { if event.state_key().unwrap().is_empty() {
tracing::warn!("state_key must be non-empty");
return Some(false); // and be non-empty state_key (point to a user_id) return Some(false); // and be non-empty state_key (point to a user_id)
} }
if event.state_key() != Some(event.sender().to_string()) { if event.state_key() != Some(event.sender().to_string()) {
tracing::warn!("no state_key field found for event");
return Some(false); return Some(false);
} }
@ -272,7 +279,7 @@ fn is_membership_change_allowed(
if event.room_id().unwrap().server_name() != target_user_id.server_name() if event.room_id().unwrap().server_name() != target_user_id.server_name()
&& !can_federate(auth_events) && !can_federate(auth_events)
{ {
tracing::info!("server cannot federate"); tracing::warn!("server cannot federate");
return Some(false); return Some(false);
} }
@ -325,23 +332,11 @@ fn is_membership_change_allowed(
if membership == MembershipState::Invite && content.third_party_invite.is_some() { if membership == MembershipState::Invite && content.third_party_invite.is_some() {
// TODO this is unimpled // TODO this is unimpled
if !verify_third_party_invite(event, auth_events) { if !verify_third_party_invite(event, auth_events) {
tracing::info!( tracing::warn!("not invited to this room",);
"{} was not invited to this room",
event
.event_id()
.map(ToString::to_string)
.unwrap_or("Unknow".into())
);
return Some(false); return Some(false);
} }
if target_banned { if target_banned {
tracing::info!( tracing::warn!("banned from this room",);
"{} is banned",
event
.event_id()
.map(ToString::to_string)
.unwrap_or("Unknow".into())
);
return Some(false); return Some(false);
} }
tracing::info!("invite succeded"); tracing::info!("invite succeded");
@ -353,15 +348,14 @@ fn is_membership_change_allowed(
&& membership == MembershipState::Leave && membership == MembershipState::Leave
&& &target_user_id == event.sender() && &target_user_id == event.sender()
{ {
tracing::info!("join event succeded"); tracing::warn!("join event succeded");
return Some(true); return Some(true);
} }
if !caller_in_room { if !caller_in_room {
tracing::info!( tracing::warn!(
"{} is not in this room {:?}", "user is not in this room {}",
event.sender(), event.room_id().unwrap().as_str(),
event.room_id()
); );
return Some(false); // caller is not joined return Some(false); // caller is not joined
} }
@ -369,10 +363,10 @@ fn is_membership_change_allowed(
if membership == MembershipState::Invite { if membership == MembershipState::Invite {
if target_banned { if target_banned {
tracing::info!("target has been banned"); tracing::warn!("target has been banned");
return Some(false); return Some(false);
} else if target_in_room { } else if target_in_room {
tracing::info!("already in room"); tracing::warn!("already in room");
return Some(false); // already in room return Some(false); // already in room
} else { } else {
let invite_level = get_named_level(auth_events, "invite", 0); let invite_level = get_named_level(auth_events, "invite", 0);
@ -382,21 +376,21 @@ fn is_membership_change_allowed(
} }
} else if membership == MembershipState::Join { } else if membership == MembershipState::Join {
if event.sender() != &target_user_id { if event.sender() != &target_user_id {
tracing::info!("cannot force another user to join"); tracing::warn!("cannot force another user to join");
return Some(false); // cannot force another user to join return Some(false); // cannot force another user to join
} else if target_banned { } else if target_banned {
tracing::info!("cannot join when banned"); tracing::warn!("cannot join when banned");
return Some(false); // cannot joined when banned return Some(false); // cannot joined when banned
} else if join_rule == JoinRule::Public { } else if join_rule == JoinRule::Public {
tracing::info!("join rule public") tracing::info!("join rule public")
// pass // pass
} else if join_rule == JoinRule::Invite { } else if join_rule == JoinRule::Invite {
if !caller_in_room && !caller_invited { if !caller_in_room && !caller_invited {
tracing::info!("user has not been invited to this room"); tracing::warn!("user has not been invited to this room");
return Some(false); // you are not invited to this room return Some(false); // you are not invited to this room
} }
} else { } else {
tracing::info!("the join rule is Private or yet to be spec'ed by Matrix"); tracing::warn!("the join rule is Private or yet to be spec'ed by Matrix");
// synapse has 2 TODO's may_join list and private rooms // synapse has 2 TODO's may_join list and private rooms
// the join_rule is Private or Knock which means it is not yet spec'ed // the join_rule is Private or Knock which means it is not yet spec'ed
@ -404,13 +398,13 @@ fn is_membership_change_allowed(
} }
} else if membership == MembershipState::Leave { } else if membership == MembershipState::Leave {
if target_banned && user_level < ban_level { if target_banned && user_level < ban_level {
tracing::info!("not enough power to unban"); tracing::warn!("not enough power to unban");
return Some(false); // you cannot unban this user return Some(false); // you cannot unban this user
} else if &target_user_id != event.sender() { } else if &target_user_id != event.sender() {
let kick_level = get_named_level(auth_events, "kick", 50); let kick_level = get_named_level(auth_events, "kick", 50);
if user_level < kick_level || user_level <= target_level { if user_level < kick_level || user_level <= target_level {
tracing::info!("not enough power to kick user"); tracing::warn!("not enough power to kick user");
return Some(false); // you do not have the power to kick user return Some(false); // you do not have the power to kick user
} }
} }
@ -423,7 +417,7 @@ fn is_membership_change_allowed(
target_level target_level
); );
if user_level < ban_level || user_level <= target_level { if user_level < ban_level || user_level <= target_level {
tracing::info!("not enough power to ban"); tracing::warn!("not enough power to ban");
return Some(false); return Some(false);
} }
} else { } else {
@ -538,7 +532,7 @@ fn check_power_levels(
let old_level_too_big = old_level > user_level; let old_level_too_big = old_level > user_level;
let new_level_too_big = new_level > user_level; let new_level_too_big = new_level > user_level;
if old_level_too_big || new_level_too_big { if old_level_too_big || new_level_too_big {
tracing::info!("m.room.power_level cannot add ops > than own"); tracing::warn!("m.room.power_level cannot add ops > than own");
return Some(false); // cannot add ops greater than own return Some(false); // cannot add ops greater than own
} }
} }
@ -557,14 +551,14 @@ fn check_power_levels(
continue; continue;
} }
if user != power_event.sender() && old_level.map(|int| (*int).into()) == Some(user_level) { if user != power_event.sender() && old_level.map(|int| (*int).into()) == Some(user_level) {
tracing::info!("m.room.power_level cannot remove ops == to own"); tracing::warn!("m.room.power_level cannot remove ops == to own");
return Some(false); // cannot remove ops level == to own return Some(false); // cannot remove ops level == to own
} }
let old_level_too_big = old_level.map(|int| (*int).into()) > Some(user_level); 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); let new_level_too_big = new_level.map(|int| (*int).into()) > Some(user_level);
if old_level_too_big || new_level_too_big { if old_level_too_big || new_level_too_big {
tracing::info!("m.room.power_level failed to add ops > than own"); tracing::warn!("m.room.power_level failed to add ops > than own");
return Some(false); // cannot add ops greater than own return Some(false); // cannot add ops greater than own
} }
} }
@ -580,7 +574,7 @@ fn check_power_levels(
let old_level_too_big = old_level.map(|int| (*int).into()) > Some(user_level); 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); let new_level_too_big = new_level.map(|int| (*int).into()) > Some(user_level);
if old_level_too_big || new_level_too_big { if old_level_too_big || new_level_too_big {
tracing::info!("m.room.power_level failed to add ops > than own"); tracing::warn!("m.room.power_level failed to add ops > than own");
return Some(false); // cannot add ops greater than own return Some(false); // cannot add ops greater than own
} }
} }
@ -602,7 +596,7 @@ fn check_power_levels(
let new_level_too_big = new_lvl > user_level; let new_level_too_big = new_lvl > user_level;
if old_level_too_big || new_level_too_big { if old_level_too_big || new_level_too_big {
tracing::info!("cannot add ops > than own"); tracing::warn!("cannot add ops > than own");
return Some(false); return Some(false);
} }
} }

48
src/lib.rs
View File

@ -79,34 +79,15 @@ impl StateResolution {
}; };
// split non-conflicting and conflicting state // split non-conflicting and conflicting state
let (clean, conflicting) = self.separate(&state_sets); let (clean, conflicting) = self.separate(&state_sets);
tracing::debug!(
"CLEAN {:#?}",
clean
.iter()
.map(|((ty, key), id)| format!("(({}{}), {})", ty, key, id))
.collect::<Vec<_>>()
);
tracing::debug!(
"CONFLICT {:#?}",
conflicting
.iter()
.map(|((ty, key), ids)| format!(
"(({} `{}`), {:?})",
ty,
key,
ids.iter().map(ToString::to_string).collect::<Vec<_>>()
))
.collect::<Vec<_>>()
);
tracing::info!("non conflicting {:?}", clean.len()); tracing::info!("non conflicting {:?}", clean.len());
if conflicting.is_empty() { if conflicting.is_empty() {
tracing::warn!("no conflicting state found"); tracing::info!("no conflicting state found");
return Ok(ResolutionResult::Resolved(clean)); return Ok(ResolutionResult::Resolved(clean));
} }
tracing::info!("computing {} conflicting events", conflicting.len()); tracing::info!("{} conflicting events", conflicting.len());
// the set of auth events that are not common across server forks // the set of auth events that are not common across server forks
let mut auth_diff = self.get_auth_chain_diff(room_id, &state_sets, store)?; let mut auth_diff = self.get_auth_chain_diff(room_id, &state_sets, store)?;
@ -167,7 +148,7 @@ impl StateResolution {
// get only the power events with a state_key: "" or ban/kick event (sender != state_key) // get only the power events with a state_key: "" or ban/kick event (sender != state_key)
let power_events = all_conflicted let power_events = all_conflicted
.iter() .iter()
.filter(|id| is_power_event(id, store)) .filter(|id| is_power_event(id, &event_map))
.cloned() .cloned()
.collect::<Vec<_>>(); .collect::<Vec<_>>();
@ -306,7 +287,6 @@ impl StateResolution {
panic!() panic!()
} }
} else { } else {
tracing::warn!("{:?}", key);
conflicted_state.insert( conflicted_state.insert(
key.clone(), key.clone(),
event_ids.into_iter().flatten().cloned().collect::<Vec<_>>(), event_ids.into_iter().flatten().cloned().collect::<Vec<_>>(),
@ -383,7 +363,7 @@ impl StateResolution {
let ev = event_map.get(event_id).unwrap(); let ev = event_map.get(event_id).unwrap();
let pl = event_to_pl.get(event_id).unwrap(); let pl = event_to_pl.get(event_id).unwrap();
tracing::warn!( tracing::debug!(
"{:?}", "{:?}",
(-*pl, *ev.origin_server_ts(), ev.event_id().cloned()) (-*pl, *ev.origin_server_ts(), ev.event_id().cloned())
); );
@ -547,7 +527,6 @@ impl StateResolution {
let mut resolved_state = unconflicted_state.clone(); let mut resolved_state = unconflicted_state.clone();
for (idx, event_id) in power_events.iter().enumerate() { for (idx, event_id) in power_events.iter().enumerate() {
tracing::warn!("POWER EVENTS {}", event_id.as_str());
let event = self let event = self
._get_event(room_id, event_id, event_map, store) ._get_event(room_id, event_id, event_map, store)
.unwrap(); .unwrap();
@ -556,7 +535,7 @@ impl StateResolution {
for aid in event.auth_events() { for aid in event.auth_events() {
if let Some(ev) = self._get_event(room_id, &aid, event_map, store) { if let Some(ev) = self._get_event(room_id, &aid, event_map, store) {
// TODO what to do when no state_key is found ?? // TODO what to do when no state_key is found ??
// TODO check "rejected_reason", I'm guessing this is redacted_because for ruma ?? // TODO synapse check "rejected_reason", I'm guessing this is redacted_because for ruma ??
auth_events.insert((ev.kind(), ev.state_key().unwrap()), ev); auth_events.insert((ev.kind(), ev.state_key().unwrap()), ev);
} else { } else {
tracing::warn!("auth event id for {} is missing {}", aid, event_id); tracing::warn!("auth event id for {} is missing {}", aid, event_id);
@ -580,7 +559,7 @@ impl StateResolution {
// add event to resolved state map // add event to resolved state map
resolved_state.insert((event.kind(), event.state_key().unwrap()), event_id.clone()); resolved_state.insert((event.kind(), event.state_key().unwrap()), event_id.clone());
} else { } else {
// TODO synapse passes here on AuthError ?? // synapse passes here on AuthError. We do not add this event to resolved_state.
tracing::warn!( tracing::warn!(
"event {} failed the authentication check", "event {} failed the authentication check",
event_id.to_string() event_id.to_string()
@ -610,11 +589,8 @@ impl StateResolution {
store: &dyn StateStore, store: &dyn StateStore,
) -> Vec<EventId> { ) -> Vec<EventId> {
tracing::debug!("mainline sort of remaining events"); tracing::debug!("mainline sort of remaining events");
// tracing::debug!(
// "{:?}", // There are no EventId's to sort, bail.
// to_sort.iter().map(ToString::to_string).collect::<Vec<_>>()
// );
// There can be no EventId's to sort, bail.
if to_sort.is_empty() { if to_sort.is_empty() {
return vec![]; return vec![];
} }
@ -692,7 +668,7 @@ impl StateResolution {
) -> usize { ) -> usize {
while let Some(sort_ev) = event { while let Some(sort_ev) = event {
tracing::debug!( tracing::debug!(
"mainline EVENT ID {}", "mainline event_id {}",
sort_ev.event_id().unwrap().to_string() sort_ev.event_id().unwrap().to_string()
); );
if let Some(id) = sort_ev.event_id() { if let Some(id) = sort_ev.event_id() {
@ -767,9 +743,9 @@ impl StateResolution {
} }
} }
pub fn is_power_event(event_id: &EventId, store: &dyn StateStore) -> bool { pub fn is_power_event(event_id: &EventId, event_map: &EventMap<StateEvent>) -> bool {
match store.get_event(event_id) { match event_map.get(event_id) {
Ok(state) => state.is_power_event(), Some(state) => state.is_power_event(),
_ => false, // TODO this shouldn't eat errors? _ => false, // TODO this shouldn't eat errors?
} }
} }

2
tests/state_res.rs
View File

@ -340,7 +340,7 @@ fn do_check(events: &[StateEvent], edges: Vec<Vec<EventId>>, expected_state_ids:
.cloned() .cloned()
.collect::<Vec<_>>(); .collect::<Vec<_>>();
tracing::warn!( tracing::debug!(
"{:#?}", "{:#?}",
state_sets state_sets
.iter() .iter()