diff --git a/bffhd/capnp/authenticationsystem.rs b/bffhd/capnp/authenticationsystem.rs index 563ab1b..56b1530 100644 --- a/bffhd/capnp/authenticationsystem.rs +++ b/bffhd/capnp/authenticationsystem.rs @@ -1,9 +1,13 @@ use capnp::capability::Promise; use capnp::Error; use capnp_rpc::pry; +use rsasl::mechname::Mechname; 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 +16,46 @@ 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 { + pub fn new( + parent: &Span, + mechanism: &Mechname, /* TODO: this is stored in session as well, get it out of there. */ + session: Session, + sessionmanager: SessionManager, + ) -> Self { + let span = tracing::info_span!( + target: TARGET, + parent: parent, + "Authentication", + mechanism = mechanism.as_str() + ); + 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 +75,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 +97,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)) => { @@ -71,11 +132,15 @@ impl AuthenticationSystem for Authentication { "Authentication didn't provide an authid as required".to_string(), ) })); - let session = pry!(manager.open(uid.as_ref()).ok_or_else(|| { + let session = pry!(manager.open(&self.span, uid.as_ref()).ok_or_else(|| { tracing::warn!(uid = uid.as_str(), "Failed to lookup the given user"); 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 +151,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 f8517e9..9595ed9 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; @@ -8,12 +10,14 @@ use crate::session::SessionManager; use capnp::capability::Promise; use capnp_rpc::pry; use rsasl::mechname::Mechname; +use tracing::Span; /// Cap'n Proto API Handler pub struct BootCap { peer_addr: SocketAddr, authentication: AuthenticationHandle, sessionmanager: SessionManager, + span: Span, } impl BootCap { @@ -21,12 +25,13 @@ impl BootCap { peer_addr: SocketAddr, authentication: AuthenticationHandle, sessionmanager: SessionManager, + span: Span, ) -> Self { - tracing::trace!(%peer_addr, "bootstrapping RPC"); Self { peer_addr, authentication, sessionmanager, + span, } } } @@ -37,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(()) } @@ -47,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(()) } @@ -60,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!(target: "bffh::api", "method call"); let builder = result.get(); let mechs: Vec<_> = self @@ -77,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(()) } @@ -85,18 +134,22 @@ 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 { if let Ok(session) = self.authentication.start(mechname) { - Authentication::new(session, self.sessionmanager.clone()) + Authentication::new(&self.span, mechname, session, self.sessionmanager.clone()) } else { Authentication::invalid_mechanism() } @@ -104,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 42ba89f..70345f7 100644 --- a/bffhd/capnp/mod.rs +++ b/bffhd/capnp/mod.rs @@ -12,7 +12,7 @@ use futures_util::{stream, AsyncRead, AsyncWrite, FutureExt, StreamExt}; use std::future::Future; use std::io; -use std::net::SocketAddr; +use std::net::{IpAddr, SocketAddr}; use crate::authentication::AuthenticationHandle; use crate::session::SessionManager; @@ -145,12 +145,36 @@ impl APIServer { peer_addr: SocketAddr, stream: impl Future>>, ) { - tracing::debug!("handling new API connection"); + let span = tracing::trace_span!("api.handle"); + let _guard = span.enter(); + + struct Peer { + ip: IpAddr, + port: u16, + } + + let peer = Peer { + ip: peer_addr.ip(), + port: peer_addr.port(), + }; + tracing::debug!( + %peer.ip, + peer.port, + "spawning api handler" + ); + + let connection_span = tracing::info_span!( + target: "bffh::api", + "connection", + %peer.ip, + peer.port, + ); let f = async move { + tracing::trace!(parent: &connection_span, "starting tls exchange"); let stream = match stream.await { Ok(stream) => stream, - Err(e) => { - tracing::error!("TLS handshake failed: {}", e); + Err(error) => { + tracing::error!(parent: &connection_span, %error, "TLS handshake failed"); return; } }; @@ -161,10 +185,15 @@ impl APIServer { peer_addr, self.authentication.clone(), self.sessionmanager.clone(), + connection_span.clone(), )); - if let Err(e) = RpcSystem::new(Box::new(vat), Some(bootstrap.client)).await { - tracing::error!("Error during RPC handling: {}", e); + if let Err(error) = RpcSystem::new(Box::new(vat), Some(bootstrap.client)).await { + tracing::error!( + parent: &connection_span, + %error, + "error occured during rpc handling", + ); } }; let cgroup = SupervisionRegistry::with(SupervisionRegistry::new_group); 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/initiators/mod.rs b/bffhd/initiators/mod.rs index e4c9714..3e24f75 100644 --- a/bffhd/initiators/mod.rs +++ b/bffhd/initiators/mod.rs @@ -17,6 +17,7 @@ use std::future::Future; use std::pin::Pin; use std::task::{Context, Poll}; use std::time::Duration; +use tracing::Span; use url::Url; mod dummy; @@ -33,12 +34,17 @@ pub trait Initiator: Future { #[derive(Clone)] pub struct InitiatorCallbacks { + span: Span, resource: Resource, sessions: SessionManager, } impl InitiatorCallbacks { - pub fn new(resource: Resource, sessions: SessionManager) -> Self { - Self { resource, sessions } + pub fn new(span: Span, resource: Resource, sessions: SessionManager) -> Self { + Self { + span, + resource, + sessions, + } } pub async fn try_update(&mut self, session: SessionHandle, status: Status) { @@ -46,17 +52,19 @@ impl InitiatorCallbacks { } pub fn open_session(&self, uid: &str) -> Option { - self.sessions.open(uid) + self.sessions.open(&self.span, uid) } } pub struct InitiatorDriver { + span: Span, name: String, initiator: Box, } impl InitiatorDriver { pub fn new( + span: Span, name: String, params: &HashMap, resource: Resource, @@ -65,9 +73,13 @@ impl InitiatorDriver { where I: 'static + Initiator + Unpin + Send, { - let callbacks = InitiatorCallbacks::new(resource, sessions); + let callbacks = InitiatorCallbacks::new(span.clone(), resource, sessions); let initiator = Box::new(I::new(params, callbacks)?); - Ok(Self { name, initiator }) + Ok(Self { + span, + name, + initiator, + }) } } @@ -133,15 +145,22 @@ fn load_single( resource: Resource, sessions: &SessionManager, ) -> Option { + let span = tracing::info_span!( + "initiator", + name = %name, + module = %module_name, + ); tracing::info!(%name, %module_name, ?params, "Loading initiator"); let o = match module_name.as_ref() { "Dummy" => Some(InitiatorDriver::new::( + span, name.clone(), params, resource, sessions.clone(), )), "Process" => Some(InitiatorDriver::new::( + span, name.clone(), params, resource, diff --git a/bffhd/lib.rs b/bffhd/lib.rs index 777b81e..ec64ef5 100644 --- a/bffhd/lib.rs +++ b/bffhd/lib.rs @@ -43,7 +43,7 @@ mod tls; use std::sync::Arc; -use futures_util::StreamExt; +use futures_util::{FutureExt, StreamExt}; use miette::{Context, IntoDiagnostic, Report}; use once_cell::sync::OnceCell; @@ -94,20 +94,17 @@ impl Diflouroborane { } tracing::info!("Server is being spawned"); let handle = executor.spawn(server.serve()); - std::thread::spawn(move || { - let result = async_io::block_on(handle); - match result { - Some(Ok(())) => { - tracing::info!("console server finished without error"); - } - Some(Err(error)) => { - tracing::info!(%error, "console server finished with error"); - } - None => { - tracing::info!("console server finished with panic"); - } + executor.spawn(handle.map(|result| match result { + Some(Ok(())) => { + tracing::info!("console server finished without error"); } - }); + Some(Err(error)) => { + tracing::info!(%error, "console server finished with error"); + } + None => { + tracing::info!("console server finished with panic"); + } + })); let env = StateDB::open_env(&config.db_path)?; diff --git a/bffhd/session/mod.rs b/bffhd/session/mod.rs index 609eefd..87eb902 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 { @@ -16,11 +17,18 @@ impl SessionManager { } // TODO: make infallible - pub fn open(&self, uid: impl AsRef) -> Option { + pub fn open(&self, parent: &Span, 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", + parent: parent, + "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 +41,8 @@ impl SessionManager { #[derive(Clone)] pub struct SessionHandle { + pub span: Span, + pub users: Users, pub roles: Roles,