From 1ff3f2afb74be24cc8dc9c7902a9d5bb50c816bd Mon Sep 17 00:00:00 2001 From: Nadja Reitzenstein Date: Fri, 24 Jun 2022 13:57:47 +0200 Subject: [PATCH] log all api calls with `TRACE` level --- bffhd/capnp/authenticationsystem.rs | 86 ++++++++++++++++++++++++++++- bffhd/capnp/connection.rs | 78 ++++++++++++++++++++++---- bffhd/capnp/machinesystem.rs | 53 ++++++++++++++++++ bffhd/capnp/mod.rs | 3 +- bffhd/capnp/permissionsystem.rs | 11 ++++ bffhd/capnp/user_system.rs | 45 ++++++++++++++- bffhd/session/mod.rs | 11 +++- 7 files changed, 270 insertions(+), 17 deletions(-) diff --git a/bffhd/capnp/authenticationsystem.rs b/bffhd/capnp/authenticationsystem.rs index 563ab1b..d530dc5 100644 --- a/bffhd/capnp/authenticationsystem.rs +++ b/bffhd/capnp/authenticationsystem.rs @@ -3,7 +3,10 @@ use capnp::Error; use capnp_rpc::pry; use rsasl::property::AuthId; use rsasl::session::{Session, Step}; +use std::fmt; +use std::fmt::{Formatter, Write}; use std::io::Cursor; +use tracing::Span; use crate::capnp::session::APISession; use crate::session::SessionManager; @@ -12,19 +15,36 @@ use api::authenticationsystem_capnp::authentication::{ }; use api::authenticationsystem_capnp::{response, response::Error as ErrorCode}; +const TARGET: &str = "bffh::api::authenticationsystem"; + pub struct Authentication { + span: Span, state: State, } impl Authentication { pub fn new(session: Session, sessionmanager: SessionManager) -> Self { + let span = tracing::info_span!(target: TARGET, "Authentication",); + tracing::trace!( + target: TARGET, + parent: &span, + "constructing valid authentication system" + ); Self { + span, state: State::Running(session, sessionmanager), } } pub fn invalid_mechanism() -> Self { + let span = tracing::info_span!(target: TARGET, "Authentication",); + tracing::trace!( + target: TARGET, + parent: &span, + "constructing invalid mechanism authentication system" + ); Self { + span, state: State::InvalidMechanism, } } @@ -44,6 +64,19 @@ impl Authentication { } } +impl fmt::Display for Authentication { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + f.write_str("Authentication(")?; + match &self.state { + State::InvalidMechanism => f.write_str("invalid mechanism")?, + State::Finished => f.write_str("finished")?, + State::Aborted => f.write_str("aborted")?, + State::Running(_, _) => f.write_str("running")?, + } + f.write_char(')') + } +} + enum State { InvalidMechanism, Finished, @@ -53,13 +86,30 @@ enum State { impl AuthenticationSystem for Authentication { fn step(&mut self, params: StepParams, mut results: StepResults) -> Promise<(), Error> { - let span = tracing::trace_span!("step"); - let _guard = span.enter(); + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "step",).entered(); + + tracing::trace!(params.data = "", "method call"); + + #[repr(transparent)] + struct Response { + union_field: &'static str, + } + impl fmt::Display for Response { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + f.write_str("Response(")?; + f.write_str(self.union_field)?; + f.write_char(')') + } + } + let mut response; + let mut builder = results.get(); if let State::Running(mut session, manager) = std::mem::replace(&mut self.state, State::Aborted) { let data: &[u8] = pry!(pry!(params.get()).get_data()); + let mut out = Cursor::new(Vec::new()); match session.step(Some(data), &mut out) { Ok(Step::Done(data)) => { @@ -76,6 +126,10 @@ impl AuthenticationSystem for Authentication { capnp::Error::failed("Failed to lookup the given user".to_string()) })); + response = Response { + union_field: "successful", + }; + let mut builder = builder.init_successful(); if data.is_some() { builder.set_additional_data(out.into_inner().as_slice()); @@ -86,21 +140,49 @@ impl AuthenticationSystem for Authentication { Ok(Step::NeedsMore(_)) => { self.state = State::Running(session, manager); builder.set_challenge(out.into_inner().as_slice()); + + response = Response { + union_field: "challenge", + }; } Err(_) => { self.state = State::Aborted; self.build_error(builder); + + response = Response { + union_field: "error", + }; } } } else { self.build_error(builder); + response = Response { + union_field: "error", + }; } + tracing::trace!( + results = %response, + "method return" + ); + Promise::ok(()) } fn abort(&mut self, _: AbortParams, _: AbortResults) -> Promise<(), Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: TARGET, + parent: &self.span, + "abort", + ) + .entered(); + + tracing::trace!("method call"); + self.state = State::Aborted; + + tracing::trace!("method return"); Promise::ok(()) } } diff --git a/bffhd/capnp/connection.rs b/bffhd/capnp/connection.rs index 1f2a265..7506649 100644 --- a/bffhd/capnp/connection.rs +++ b/bffhd/capnp/connection.rs @@ -1,5 +1,7 @@ use api::connection_capnp::bootstrap; pub use api::connection_capnp::bootstrap::Client; +use std::fmt; +use std::fmt::{Formatter, Write}; use std::net::SocketAddr; use crate::authentication::AuthenticationHandle; @@ -25,7 +27,6 @@ impl BootCap { sessionmanager: SessionManager, span: Span, ) -> Self { - tracing::trace!(parent: &span, %peer_addr, "bootstrapping RPC"); Self { peer_addr, authentication, @@ -41,8 +42,14 @@ impl bootstrap::Server for BootCap { _: bootstrap::GetAPIVersionParams, _: bootstrap::GetAPIVersionResults, ) -> Promise<(), ::capnp::Error> { - let span = tracing::trace_span!("get_api_version", peer_addr=%self.peer_addr); - let _guard = span.enter(); + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: "bffh::api", + "Bootstrap", + method = "getAPIVersion", + ) + .entered(); + tracing::trace!("method call"); Promise::ok(()) } @@ -51,11 +58,24 @@ impl bootstrap::Server for BootCap { _: bootstrap::GetServerReleaseParams, mut result: bootstrap::GetServerReleaseResults, ) -> Promise<(), ::capnp::Error> { - let span = tracing::trace_span!("get_server_release", peer_addr=%self.peer_addr); - let _guard = span.enter(); + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: "bffh::api", + "Bootstrap", + method = "getServerRelease", + ) + .entered(); + tracing::trace!("method call"); + let mut builder = result.get(); builder.set_name("bffhd"); builder.set_release(crate::env::VERSION); + + tracing::trace!( + results.name = "bffhd", + results.release = crate::env::VERSION, + "method return" + ); Promise::ok(()) } @@ -64,10 +84,13 @@ impl bootstrap::Server for BootCap { _params: bootstrap::MechanismsParams, mut result: bootstrap::MechanismsResults, ) -> Promise<(), ::capnp::Error> { - let span = tracing::trace_span!("mechanisms", peer_addr=%self.peer_addr); - let _guard = span.enter(); - - tracing::trace!("mechanisms"); + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: "bffh::api", + "mechanisms", + ) + .entered(); + tracing::trace!("method call"); let builder = result.get(); let mechs: Vec<_> = self @@ -81,6 +104,28 @@ impl bootstrap::Server for BootCap { mechbuilder.set(i as u32, m); } + struct DisMechs<'a>(Vec<&'a str>); + impl fmt::Display for DisMechs<'_> { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + f.write_char('[')?; + let mut first = true; + for mechanism in self.0.iter() { + if first { + first = false; + f.write_str(mechanism)?; + } else { + f.write_str(" ,")?; + f.write_str(mechanism)?; + } + } + f.write_char(']')?; + Ok(()) + } + } + tracing::trace!( + results.mechs = %DisMechs(mechs), + "method return" + ); Promise::ok(()) } @@ -89,13 +134,17 @@ impl bootstrap::Server for BootCap { params: bootstrap::CreateSessionParams, mut result: bootstrap::CreateSessionResults, ) -> Promise<(), ::capnp::Error> { - let span = tracing::trace_span!("create_session", peer_addr=%self.peer_addr); - let _guard = span.enter(); + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: "bffh::api", + "createSession", + ) + .entered(); let params = pry!(params.get()); let mechanism: &str = pry!(params.get_mechanism()); - tracing::trace!(mechanism); + tracing::trace!(params.mechanism = mechanism, "method call"); let mechname = Mechname::new(mechanism.as_bytes()); let auth = if let Ok(mechname) = mechname { @@ -108,6 +157,11 @@ impl bootstrap::Server for BootCap { Authentication::invalid_mechanism() }; + tracing::trace!( + results.authentication = %auth, + "method return" + ); + let mut builder = result.get(); builder.set_authentication(capnp_rpc::new_client(auth)); diff --git a/bffhd/capnp/machinesystem.rs b/bffhd/capnp/machinesystem.rs index 729bd87..fad4240 100644 --- a/bffhd/capnp/machinesystem.rs +++ b/bffhd/capnp/machinesystem.rs @@ -6,17 +6,27 @@ use crate::RESOURCES; use api::machinesystem_capnp::machine_system::info; use capnp::capability::Promise; use capnp_rpc::pry; +use tracing::Span; + +const TARGET: &str = "bffh::api::machinesystem"; #[derive(Clone)] pub struct Machines { + span: Span, session: SessionHandle, resources: ResourcesHandle, } impl Machines { pub fn new(session: SessionHandle) -> Self { + let span = tracing::info_span!( + target: TARGET, + parent: &session.span, + "MachineSystem", + ); // FIXME no unwrap bad Self { + span, session, resources: RESOURCES.get().unwrap().clone(), } @@ -29,6 +39,16 @@ impl info::Server for Machines { _: info::GetMachineListParams, mut result: info::GetMachineListResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: TARGET, + parent: &self.span, + "getMachineList", + ) + .entered(); + + tracing::trace!("method call"); + let machine_list: Vec<(usize, &Resource)> = self .resources .list_all() @@ -43,6 +63,9 @@ impl info::Server for Machines { Machine::build(self.session.clone(), resource, mbuilder); } + // TODO: indicate result? + tracing::trace!("method return"); + Promise::ok(()) } @@ -51,12 +74,25 @@ impl info::Server for Machines { params: info::GetMachineParams, mut result: info::GetMachineResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: TARGET, + parent: &self.span, + "getMachine", + ) + .entered(); + let params = pry!(params.get()); let id = pry!(params.get_id()); + tracing::trace!(params.id = id, "method call"); + if let Some(resource) = self.resources.get_by_id(id) { + tracing::trace!(results = "Just", results.inner = id, "method return"); let builder = result.get(); Machine::optional_build(self.session.clone(), resource.clone(), builder); + } else { + tracing::trace!(results = "Nothing", "method return"); } Promise::ok(()) @@ -67,12 +103,29 @@ impl info::Server for Machines { params: info::GetMachineURNParams, mut result: info::GetMachineURNResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!( + target: TARGET, + parent: &self.span, + "getMachineURN", + ) + .entered(); + let params = pry!(params.get()); let urn = pry!(params.get_urn()); + tracing::trace!(params.urn = urn, "method call"); + if let Some(resource) = self.resources.get_by_urn(urn) { + tracing::trace!( + results = "Just", + results.inner = resource.get_id(), + "method return" + ); let builder = result.get(); Machine::optional_build(self.session.clone(), resource.clone(), builder); + } else { + tracing::trace!(results = "Nothing", "method return"); } Promise::ok(()) diff --git a/bffhd/capnp/mod.rs b/bffhd/capnp/mod.rs index e127ac0..9dc3db1 100644 --- a/bffhd/capnp/mod.rs +++ b/bffhd/capnp/mod.rs @@ -164,7 +164,8 @@ impl APIServer { ); let connection_span = tracing::info_span!( - "rpcsystem", + target: "bffh::api", + "Bootstrap", %peer.ip, peer.port, ); diff --git a/bffhd/capnp/permissionsystem.rs b/bffhd/capnp/permissionsystem.rs index 199e5c0..6e8eac3 100644 --- a/bffhd/capnp/permissionsystem.rs +++ b/bffhd/capnp/permissionsystem.rs @@ -5,16 +5,22 @@ use api::permissionsystem_capnp::permission_system::info::{ }; use capnp::capability::Promise; use capnp::Error; +use tracing::Span; use crate::session::SessionHandle; +const TARGET: &str = "bffh::api::permissionsystem"; + pub struct Permissions { + span: Span, roles: Roles, } impl Permissions { pub fn new(session: SessionHandle) -> Self { + let span = tracing::info_span!(target: TARGET, "PermissionSystem",); Self { + span, roles: session.roles, } } @@ -26,6 +32,10 @@ impl PermissionSystem for Permissions { _: GetRoleListParams, mut results: GetRoleListResults, ) -> Promise<(), Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "getRoleList",).entered(); + + tracing::trace!("method call"); let roles = self.roles.list().collect::>(); let mut builder = results.get(); let mut b = builder.init_role_list(roles.len() as u32); @@ -33,6 +43,7 @@ impl PermissionSystem for Permissions { let mut role_builder = b.reborrow().get(i as u32); role_builder.set_name(role); } + tracing::trace!("method return"); Promise::ok(()) } } diff --git a/bffhd/capnp/user_system.rs b/bffhd/capnp/user_system.rs index b79215d..2c735d9 100644 --- a/bffhd/capnp/user_system.rs +++ b/bffhd/capnp/user_system.rs @@ -1,20 +1,25 @@ use api::usersystem_capnp::user_system::{info, manage, search}; use capnp::capability::Promise; use capnp_rpc::pry; +use tracing::Span; use crate::capnp::user::User; use crate::session::SessionHandle; use crate::users::{db, UserRef}; +const TARGET: &str = "bffh::api::usersystem"; + #[derive(Clone)] pub struct Users { + span: Span, session: SessionHandle, } impl Users { pub fn new(session: SessionHandle) -> Self { - Self { session } + let span = tracing::info_span!(target: TARGET, "UserSystem",); + Self { span, session } } } @@ -24,8 +29,14 @@ impl info::Server for Users { _: info::GetUserSelfParams, mut result: info::GetUserSelfResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "getUserSelf").entered(); + tracing::trace!("method call"); + let builder = result.get(); User::build(self.session.clone(), builder); + + tracing::trace!("method return"); Promise::ok(()) } } @@ -36,6 +47,10 @@ impl manage::Server for Users { _: manage::GetUserListParams, mut result: manage::GetUserListResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "getUserList",).entered(); + tracing::trace!("method call"); + let userdb = self.session.users.into_inner(); let users = pry!(userdb .get_all() @@ -44,18 +59,30 @@ impl manage::Server for Users { for (i, (_, user)) in users.into_iter().enumerate() { User::fill(&self.session, user, builder.reborrow().get(i as u32)); } + + tracing::trace!("method return"); Promise::ok(()) } + fn add_user_fallible( &mut self, params: manage::AddUserFallibleParams, mut result: manage::AddUserFallibleResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "addUserFallible").entered(); + let params = pry!(params.get()); let username = pry!(params.get_username()); let password = pry!(params.get_password()); // FIXME: saslprep passwords & usernames before storing them + tracing::trace!( + params.username = username, + params.password = "", + "method call" + ); + let mut builder = result.get(); if !username.is_empty() && !password.is_empty() { @@ -81,21 +108,29 @@ impl manage::Server for Users { } } + tracing::trace!("method return"); Promise::ok(()) } + fn remove_user( &mut self, params: manage::RemoveUserParams, _: manage::RemoveUserResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "removeUser",).entered(); + let who: &str = pry!(pry!(pry!(params.get()).get_user()).get_username()); + tracing::trace!(params.user = who, "method call"); + if let Err(e) = self.session.users.del_user(who) { tracing::warn!("Failed to delete user: {:?}", e); } else { tracing::info!("Deleted user {}", who); } + tracing::trace!("method return"); Promise::ok(()) } } @@ -106,9 +141,17 @@ impl search::Server for Users { params: search::GetUserByNameParams, mut result: search::GetUserByNameResults, ) -> Promise<(), ::capnp::Error> { + let _guard = self.span.enter(); + let _span = tracing::trace_span!(target: TARGET, "getUserByName",).entered(); + let username: &str = pry!(pry!(params.get()).get_username()); + + tracing::trace!(params.username = username, "method call"); + let userref = UserRef::new(username.to_string()); User::build_optional(&self.session, Some(userref), result.get()); + + tracing::trace!("method return"); Promise::ok(()) } } diff --git a/bffhd/session/mod.rs b/bffhd/session/mod.rs index 609eefd..8533640 100644 --- a/bffhd/session/mod.rs +++ b/bffhd/session/mod.rs @@ -3,6 +3,7 @@ use crate::authorization::roles::Roles; use crate::resources::Resource; use crate::users::{db, UserRef}; use crate::Users; +use tracing::Span; #[derive(Clone)] pub struct SessionManager { @@ -19,8 +20,14 @@ impl SessionManager { pub fn open(&self, uid: impl AsRef) -> Option { let uid = uid.as_ref(); if let Some(user) = self.users.get_user(uid) { - tracing::trace!(uid, ?user, "opening new session for user"); + let span = tracing::info_span!( + target: "bffh::api", + "session", + uid = uid, + ); + tracing::trace!(parent: &span, uid, ?user, "opening session"); Some(SessionHandle { + span, users: self.users.clone(), roles: self.roles.clone(), user: UserRef::new(user.id), @@ -33,6 +40,8 @@ impl SessionManager { #[derive(Clone)] pub struct SessionHandle { + pub span: Span, + pub users: Users, pub roles: Roles,