Merge branch 'feature/spanned-api-handling' into development

* feature/spanned-api-handling:
  Output plentiful trace info for API calls
  log all api calls with `TRACE` level
  Add a connection-specific span to each API handler
This commit is contained in:
Nadja Reitzenstein 2022-06-24 14:35:41 +02:00
commit e1377d0f79
9 changed files with 358 additions and 45 deletions

View File

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

View File

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

View File

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

View File

@ -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<Output = io::Result<TlsStream<IO>>>,
) {
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);

View File

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

View File

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

View File

@ -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<Output = ()> {
#[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<SessionHandle> {
self.sessions.open(uid)
self.sessions.open(&self.span, uid)
}
}
pub struct InitiatorDriver {
span: Span,
name: String,
initiator: Box<dyn Initiator + Unpin + Send>,
}
impl InitiatorDriver {
pub fn new<I>(
span: Span,
name: String,
params: &HashMap<String, String>,
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<InitiatorDriver> {
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::<Dummy>(
span,
name.clone(),
params,
resource,
sessions.clone(),
)),
"Process" => Some(InitiatorDriver::new::<Process>(
span,
name.clone(),
params,
resource,

View File

@ -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,9 +94,7 @@ 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 {
executor.spawn(handle.map(|result| match result {
Some(Ok(())) => {
tracing::info!("console server finished without error");
}
@ -106,8 +104,7 @@ impl Diflouroborane {
None => {
tracing::info!("console server finished with panic");
}
}
});
}));
let env = StateDB::open_env(&config.db_path)?;

View File

@ -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<str>) -> Option<SessionHandle> {
pub fn open(&self, parent: &Span, 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",
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,