TudbuT/conduit
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

improve various logging

Browse source 
Signed-off-by: Jason Volk <jason@zemos.net>
This commit is contained in:
Jason Volk 2024-04-23 11:34:20 -07:00 • committed by June
parent 57e6af6e21
commit 15a990dc25
5 changed files with 33 additions and 78 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
src/api/client_server/membership.rs
View file

@ -1281,7 +1281,7 @@ pub(crate) async fn join_room_by_id_helper(
services() services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(&remote_server, &signed_event_id, room_id, signed_value, true, &pub_key_map) .handle_incoming_pdu(&remote_server, room_id, &signed_event_id, signed_value, true, &pub_key_map)
.await?; .await?;
} else { } else {
return Err(error); return Err(error);
@ -1538,7 +1538,7 @@ pub(crate) async fn invite_helper(
let pdu_id: Vec<u8> = services() let pdu_id: Vec<u8> = services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(&origin, &event_id, room_id, value, true, &pub_key_map) .handle_incoming_pdu(&origin, room_id, &event_id, value, true, &pub_key_map)
.await? .await?
.ok_or(Error::BadRequest( .ok_or(Error::BadRequest(
ErrorKind::InvalidParam, ErrorKind::InvalidParam,

96
src/api/server_server.rs
View file

@ -49,10 +49,11 @@ use ruma::{
}; };
use serde_json::value::{to_raw_value, RawValue as RawJsonValue}; use serde_json::value::{to_raw_value, RawValue as RawJsonValue};
use tokio::sync::RwLock; use tokio::sync::RwLock;
use tracing::{debug, error, info, trace, warn}; use tracing::{debug, error, trace, warn};
use crate::{ use crate::{
api::client_server::{self, claim_keys_helper, get_keys_helper}, api::client_server::{self, claim_keys_helper, get_keys_helper},
debug_error,
service::pdu::{gen_event_id_canonical_json, PduBuilder}, service::pdu::{gen_event_id_canonical_json, PduBuilder},
services, utils, Error, PduEvent, Result, Ruma, services, utils, Error, PduEvent, Result, Ruma,
}; };
@ -155,10 +156,7 @@ pub(crate) async fn get_public_rooms_filtered_route(
&body.room_network, &body.room_network,
) )
.await .await
.map_err(|e| { .map_err(|_| Error::BadRequest(ErrorKind::Unknown, "Failed to return this server's public room list."))?;
warn!("Failed to return our /publicRooms: {e}");
Error::BadRequest(ErrorKind::Unknown, "Failed to return this server's public room list.")
})?;
Ok(get_public_rooms_filtered::v1::Response { Ok(get_public_rooms_filtered::v1::Response {
chunk: response.chunk, chunk: response.chunk,
@ -189,10 +187,7 @@ pub(crate) async fn get_public_rooms_route(
&body.room_network, &body.room_network,
) )
.await .await
.map_err(|e| { .map_err(|_| Error::BadRequest(ErrorKind::Unknown, "Failed to return this server's public room list."))?;
warn!("Failed to return our /publicRooms: {e}");
Error::BadRequest(ErrorKind::Unknown, "Failed to return this server's public room list.")
})?;
Ok(get_public_rooms::v1::Response { Ok(get_public_rooms::v1::Response {
chunk: response.chunk, chunk: response.chunk,
@ -308,7 +303,7 @@ pub(crate) async fn send_transaction_message_route(
services() services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(sender_servername, &event_id, &room_id, value, true, &pub_key_map) .handle_incoming_pdu(sender_servername, &room_id, &event_id, value, true, &pub_key_map)
.await .await
.map(|_| ()), .map(|_| ()),
); );
@ -390,7 +385,7 @@ pub(crate) async fn send_transaction_message_route(
.readreceipt_update(&user_id, &room_id, event)?; .readreceipt_update(&user_id, &room_id, event)?;
} else { } else {
// TODO fetch missing events // TODO fetch missing events
debug!("No known event ids in read receipt: {:?}", user_updates); debug_error!("No known event ids in read receipt: {:?}", user_updates);
} }
} }
} }
@ -453,7 +448,7 @@ pub(crate) async fn send_transaction_message_route(
target_device_id, target_device_id,
&ev_type.to_string(), &ev_type.to_string(),
event.deserialize_as().map_err(|e| { event.deserialize_as().map_err(|e| {
warn!("To-Device event is invalid: {event:?} {e}"); error!("To-Device event is invalid: {event:?} {e}");
Error::BadRequest(ErrorKind::InvalidParam, "Event is invalid") Error::BadRequest(ErrorKind::InvalidParam, "Event is invalid")
})?, })?,
)?; )?;
@ -532,10 +527,7 @@ pub(crate) async fn get_event_route(body: Ruma<get_event::v1::Request>) -> Resul
.rooms .rooms
.timeline .timeline
.get_pdu_json(&body.event_id)? .get_pdu_json(&body.event_id)?
.ok_or_else(|| { .ok_or_else(|| Error::BadRequest(ErrorKind::NotFound, "Event not found."))?;
warn!("Event not found, event ID: {:?}", &body.event_id);
Error::BadRequest(ErrorKind::NotFound, "Event not found.")
})?;
let room_id_str = event let room_id_str = event
.get("room_id") .get("room_id")
@ -578,8 +570,6 @@ pub(crate) async fn get_backfill_route(body: Ruma<get_backfill::v1::Request>) ->
.as_ref() .as_ref()
.expect("server is authenticated"); .expect("server is authenticated");
debug!("Got backfill request from: {}", sender_servername);
if !services() if !services()
.rooms .rooms
.state_cache .state_cache
@ -671,11 +661,7 @@ pub(crate) async fn get_missing_events_route(
.map_err(|_| Error::bad_database("Invalid room id field in event in database"))?; .map_err(|_| Error::bad_database("Invalid room id field in event in database"))?;
if event_room_id != body.room_id { if event_room_id != body.room_id {
warn!( return Err(Error::BadRequest(ErrorKind::InvalidParam, "Event from wrong room"));
"Evil event detected: Event {} found while searching in room {}",
queued_events[i], body.room_id
);
return Err(Error::BadRequest(ErrorKind::InvalidParam, "Evil event detected"));
} }
if body.earliest_events.contains(&queued_events[i]) { if body.earliest_events.contains(&queued_events[i]) {
@ -743,10 +729,7 @@ pub(crate) async fn get_event_authorization_route(
.rooms .rooms
.timeline .timeline
.get_pdu_json(&body.event_id)? .get_pdu_json(&body.event_id)?
.ok_or_else(|| { .ok_or_else(|| Error::BadRequest(ErrorKind::NotFound, "Event not found."))?;
warn!("Event not found, event ID: {:?}", &body.event_id);
Error::BadRequest(ErrorKind::NotFound, "Event not found.")
})?;
let room_id_str = event let room_id_str = event
.get("room_id") .get("room_id")
@ -827,12 +810,12 @@ pub(crate) async fn get_room_state_route(
Ok(get_room_state::v1::Response { Ok(get_room_state::v1::Response {
auth_chain: auth_chain_ids auth_chain: auth_chain_ids
.filter_map(|id| { .filter_map(|id| {
if let Some(json) = services().rooms.timeline.get_pdu_json(&id).ok()? { services()
Some(PduEvent::convert_to_outgoing_federation_event(json)) .rooms
} else { .timeline
error!("Could not find event json for {id} in db."); .get_pdu_json(&id)
None .ok()?
} .map(PduEvent::convert_to_outgoing_federation_event)
}) })
.collect(), .collect(),
pdus, pdus,
@ -961,10 +944,8 @@ pub(crate) async fn create_join_event_template_route(
let join_rules_event_content: Option<RoomJoinRulesEventContent> = join_rules_event let join_rules_event_content: Option<RoomJoinRulesEventContent> = join_rules_event
.as_ref() .as_ref()
.map(|join_rules_event| { .map(|join_rules_event| {
serde_json::from_str(join_rules_event.content.get()).map_err(|e| { serde_json::from_str(join_rules_event.content.get())
warn!("Invalid join rules event: {}", e); .map_err(|_| Error::bad_database("Invalid join rules event in db."))
Error::bad_database("Invalid join rules event in db.")
})
}) })
.transpose()?; .transpose()?;
@ -1150,10 +1131,7 @@ async fn create_join_event(
&mut value, &mut value,
&room_version_id, &room_version_id,
) )
.map_err(|e| { .map_err(|_| Error::BadRequest(ErrorKind::InvalidParam, "Failed to sign event."))?;
warn!("Failed to sign event: {e}");
Error::BadRequest(ErrorKind::InvalidParam, "Failed to sign event.")
})?;
let origin: OwnedServerName = serde_json::from_value( let origin: OwnedServerName = serde_json::from_value(
serde_json::to_value( serde_json::to_value(
@ -1184,7 +1162,7 @@ async fn create_join_event(
let pdu_id: Vec<u8> = services() let pdu_id: Vec<u8> = services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(&origin, &event_id, room_id, value.clone(), true, &pub_key_map) .handle_incoming_pdu(&origin, room_id, &event_id, value.clone(), true, &pub_key_map)
.await? .await?
.ok_or(Error::BadRequest( .ok_or(Error::BadRequest(
ErrorKind::InvalidParam, ErrorKind::InvalidParam,
@ -1294,11 +1272,6 @@ pub(crate) async fn create_join_event_v2_route(
.forbidden_remote_server_names .forbidden_remote_server_names
.contains(sender_servername) .contains(sender_servername)
{ {
warn!(
"Server {sender_servername} tried joining room ID {} who has a server name that is globally forbidden. \
Rejecting.",
&body.room_id,
);
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Server is banned on this homeserver.", "Server is banned on this homeserver.",
@ -1408,7 +1381,6 @@ pub(crate) async fn create_leave_event_template_route(
pdu_json.remove("event_id"); pdu_json.remove("event_id");
}, },
_ => { _ => {
warn!("Unexpected or unsupported room version {room_version_id}");
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::BadJson, ErrorKind::BadJson,
"Unexpected or unsupported room version found", "Unexpected or unsupported room version found",
@ -1468,7 +1440,7 @@ async fn create_leave_event(sender_servername: &ServerName, room_id: &RoomId, pd
let pdu_id: Vec<u8> = services() let pdu_id: Vec<u8> = services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(&origin, &event_id, room_id, value, true, &pub_key_map) .handle_incoming_pdu(&origin, room_id, &event_id, value, true, &pub_key_map)
.await? .await?
.ok_or(Error::BadRequest( .ok_or(Error::BadRequest(
ErrorKind::InvalidParam, ErrorKind::InvalidParam,
@ -1555,11 +1527,6 @@ pub(crate) async fn create_invite_route(body: Ruma<create_invite::v2::Request>)
.forbidden_remote_server_names .forbidden_remote_server_names
.contains(&server.to_owned()) .contains(&server.to_owned())
{ {
warn!(
"Received federated/remote invite from server {sender_servername} for room ID {} which has a banned \
server name. Rejecting.",
body.room_id
);
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"Server is banned on this homeserver.", "Server is banned on this homeserver.",
@ -1589,10 +1556,8 @@ pub(crate) async fn create_invite_route(body: Ruma<create_invite::v2::Request>)
} }
} }
let mut signed_event = utils::to_canonical_object(&body.event).map_err(|e| { let mut signed_event = utils::to_canonical_object(&body.event)
error!("Failed to convert invite event to canonical JSON: {}", e); .map_err(|_| Error::BadRequest(ErrorKind::InvalidParam, "Invite event is invalid."))?;
Error::BadRequest(ErrorKind::InvalidParam, "Invite event is invalid.")
})?;
ruma::signatures::hash_and_sign_event( ruma::signatures::hash_and_sign_event(
services().globals.server_name().as_str(), services().globals.server_name().as_str(),
@ -1632,10 +1597,6 @@ pub(crate) async fn create_invite_route(body: Ruma<create_invite::v2::Request>)
.map_err(|_| Error::BadRequest(ErrorKind::InvalidParam, "state_key is not a user id."))?; .map_err(|_| Error::BadRequest(ErrorKind::InvalidParam, "state_key is not a user id."))?;
if services().rooms.metadata.is_banned(&body.room_id)? && !services().users.is_admin(&invited_user)? { if services().rooms.metadata.is_banned(&body.room_id)? && !services().users.is_admin(&invited_user)? {
info!(
"Received remote invite from server {} for room {} and for user {invited_user}, but room is banned by us.",
&sender_servername, &body.room_id
);
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"This room is banned on this homeserver.", "This room is banned on this homeserver.",
@ -1643,11 +1604,6 @@ pub(crate) async fn create_invite_route(body: Ruma<create_invite::v2::Request>)
} }
if services().globals.block_non_admin_invites() && !services().users.is_admin(&invited_user)? { if services().globals.block_non_admin_invites() && !services().users.is_admin(&invited_user)? {
info!(
"Received remote invite from server {} for room {} and for user {invited_user} who is not an admin, but \
\"block_non_admin_invites\" is enabled, rejecting.",
&sender_servername, &body.room_id
);
return Err(Error::BadRequest( return Err(Error::BadRequest(
ErrorKind::forbidden(), ErrorKind::forbidden(),
"This server does not allow room invites.", "This server does not allow room invites.",
@ -1661,10 +1617,8 @@ pub(crate) async fn create_invite_route(body: Ruma<create_invite::v2::Request>)
event.insert("event_id".to_owned(), "$placeholder".into()); event.insert("event_id".to_owned(), "$placeholder".into());
let pdu: PduEvent = serde_json::from_value(event.into()).map_err(|e| { let pdu: PduEvent = serde_json::from_value(event.into())
warn!("Invalid invite event: {}", e); .map_err(|_| Error::BadRequest(ErrorKind::InvalidParam, "Invalid invite event."))?;
Error::BadRequest(ErrorKind::InvalidParam, "Invalid invite event.")
})?;
invite_state.push(pdu.to_stripped_state_event()); invite_state.push(pdu.to_stripped_state_event());

7
src/service/rooms/event_handler/mod.rs
View file

@ -25,6 +25,7 @@ use tracing::{debug, error, info, trace, warn};
use super::state_compressor::CompressedStateEvent; use super::state_compressor::CompressedStateEvent;
use crate::{ use crate::{
debug_info,
service::{pdu, Arc, BTreeMap, HashMap, Result}, service::{pdu, Arc, BTreeMap, HashMap, Result},
services, Error, PduEvent, services, Error, PduEvent,
}; };
@ -70,7 +71,7 @@ impl Service {
/// room, if not soft fail it /// room, if not soft fail it
#[tracing::instrument(skip(self, origin, value, is_timeline_event, pub_key_map), name = "pdu")] #[tracing::instrument(skip(self, origin, value, is_timeline_event, pub_key_map), name = "pdu")]
pub(crate) async fn handle_incoming_pdu<'a>( pub(crate) async fn handle_incoming_pdu<'a>(
&self, origin: &'a ServerName, event_id: &'a EventId, room_id: &'a RoomId, &self, origin: &'a ServerName, room_id: &'a RoomId, event_id: &'a EventId,
value: BTreeMap<String, CanonicalJsonValue>, is_timeline_event: bool, value: BTreeMap<String, CanonicalJsonValue>, is_timeline_event: bool,
pub_key_map: &'a RwLock<BTreeMap<String, BTreeMap<String, Base64>>>, pub_key_map: &'a RwLock<BTreeMap<String, BTreeMap<String, Base64>>>,
) -> Result<Option<Vec<u8>>> { ) -> Result<Option<Vec<u8>>> {
@ -647,9 +648,9 @@ impl Service {
// Event has passed all auth/stateres checks // Event has passed all auth/stateres checks
drop(state_lock); drop(state_lock);
debug!( debug_info!(
elapsed = ?timer.elapsed(), elapsed = ?timer.elapsed(),
"Appended incoming pdu", "Accepted",
); );
Ok(pdu_id) Ok(pdu_id)

2
src/service/rooms/timeline/mod.rs
View file

@ -1183,7 +1183,7 @@ impl Service {
services() services()
.rooms .rooms
.event_handler .event_handler
.handle_incoming_pdu(origin, &event_id, &room_id, value, false, pub_key_map) .handle_incoming_pdu(origin, &room_id, &event_id, value, false, pub_key_map)
.await?; .await?;
let value = self.get_pdu_json(&event_id)?.expect("We just created it"); let value = self.get_pdu_json(&event_id)?.expect("We just created it");

2
src/service/sending/send.rs
View file

@ -437,7 +437,7 @@ fn handle_resolve_error(e: &ResolveError) -> Result<()> {
Ok(()) Ok(())
}, },
_ => { _ => {
error!("{e}"); error!("DNS {e}");
Err(Error::Err(e.to_string())) Err(Error::Err(e.to_string()))
}, },
} }