log all api calls with TRACE level

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 = "<authentication 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(())
     }
 }

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));
 

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

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,
         );

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::<Vec<&String>>();
         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(())
     }
 }

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 = "<redacted>",
+            "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(())
     }
 }

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<str>) -> Option<SessionHandle> {
         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,