server: Update tracing-forest and take advantage of the span fields

Cargo.lock

@@ -4360,9 +4360,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-forest"
-version = "0.1.5"
+version = "0.1.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "119324027fc01804d9f83aefb7d80fda2e8fbe7c28e0acc59187cbd751a12915"
+checksum = "ee40835db14ddd1e3ba414292272eddde9dad04d3d4b65509656414d1c42592f"
 dependencies = [
  "chrono",
  "smallvec",

Cargo.toml

@@ -9,6 +9,8 @@ members = [
 
 default-members = ["server"]
 
+resolver = "2"
+
 [profile.release]
 lto = true
 

server/Cargo.toml

@@ -101,7 +101,7 @@ version = "*"
 
 [dependencies.tracing-forest]
 features = ["smallvec", "chrono", "tokio"]
-version = "^0.1.4"
+version = "^0.1.6"
 
 [dependencies.actix-tls]
 features = ["default", "rustls"]

server/src/domain/ldap/group.rs

@@ -198,14 +198,13 @@ fn convert_group_filter(
     }
 }
 
-#[instrument(skip_all, level = "debug")]
+#[instrument(skip_all, level = "debug", fields(ldap_filter))]
 pub async fn get_groups_list<Backend: GroupListerBackendHandler>(
     ldap_info: &LdapInfo,
     ldap_filter: &LdapFilter,
     base: &str,
     backend: &Backend,
 ) -> LdapResult<Vec<Group>> {
-    debug!(?ldap_filter);
     let filters = convert_group_filter(ldap_info, ldap_filter)?;
     debug!(?filters);
     backend

server/src/domain/ldap/user.rs

@@ -230,7 +230,7 @@ fn expand_user_attribute_wildcards(attributes: &[String]) -> Vec<&str> {
     expand_attribute_wildcards(attributes, ALL_USER_ATTRIBUTE_KEYS)
 }
 
-#[instrument(skip_all, level = "debug")]
+#[instrument(skip_all, level = "debug", fields(ldap_filter, request_groups))]
 pub async fn get_user_list<Backend: UserListerBackendHandler>(
     ldap_info: &LdapInfo,
     ldap_filter: &LdapFilter,
@@ -238,7 +238,6 @@ pub async fn get_user_list<Backend: UserListerBackendHandler>(
     base: &str,
     backend: &Backend,
 ) -> LdapResult<Vec<UserAndGroups>> {
-    debug!(?ldap_filter);
     let filters = convert_user_filter(ldap_info, ldap_filter)?;
     debug!(?filters);
     backend

server/src/domain/ldap/utils.rs

@@ -106,7 +106,7 @@ pub fn get_group_id_from_distinguished_name(
     get_id_from_distinguished_name(dn, base_tree, base_dn_str, true)
 }
 
-#[instrument(skip_all, level = "debug")]
+#[instrument(skip(all_attribute_keys), level = "debug")]
 pub fn expand_attribute_wildcards<'a>(
     ldap_attributes: &'a [String],
     all_attribute_keys: &'a [&'static str],
@@ -128,7 +128,7 @@ pub fn expand_attribute_wildcards<'a>(
         .into_iter()
         .unique_by(|a| a.to_ascii_lowercase())
         .collect_vec();
-    debug!(?ldap_attributes, ?resolved_attributes);
+    debug!(?resolved_attributes);
     resolved_attributes
 }
 

server/src/domain/sql_group_backend_handler.rs

@@ -13,7 +13,7 @@ use sea_orm::{
     ActiveModelTrait, ActiveValue, ColumnTrait, EntityTrait, QueryFilter, QueryOrder, QuerySelect,
     QueryTrait,
 };
-use tracing::{debug, instrument};
+use tracing::instrument;
 
 fn get_group_filter_expr(filter: GroupRequestFilter) -> Cond {
     use GroupRequestFilter::*;
@@ -60,9 +60,8 @@ fn get_group_filter_expr(filter: GroupRequestFilter) -> Cond {
 
 #[async_trait]
 impl GroupListerBackendHandler for SqlBackendHandler {
-    #[instrument(skip_all, level = "debug", ret, err)]
+    #[instrument(skip(self), level = "debug", ret, err)]
     async fn list_groups(&self, filters: Option<GroupRequestFilter>) -> Result<Vec<Group>> {
-        debug!(?filters);
         let results = model::Group::find()
             // The order_by must be before find_with_related otherwise the primary order is by group_id.
             .order_by_asc(GroupColumn::DisplayName)
@@ -100,9 +99,8 @@ impl GroupListerBackendHandler for SqlBackendHandler {
 
 #[async_trait]
 impl GroupBackendHandler for SqlBackendHandler {
-    #[instrument(skip_all, level = "debug", ret, err)]
+    #[instrument(skip(self), level = "debug", ret, err)]
     async fn get_group_details(&self, group_id: GroupId) -> Result<GroupDetails> {
-        debug!(?group_id);
         model::Group::find_by_id(group_id)
             .into_model::<GroupDetails>()
             .one(&self.sql_pool)
@@ -110,9 +108,8 @@ impl GroupBackendHandler for SqlBackendHandler {
             .ok_or_else(|| DomainError::EntityNotFound(format!("{:?}", group_id)))
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip(self), level = "debug", err, fields(group_id = ?request.group_id))]
     async fn update_group(&self, request: UpdateGroupRequest) -> Result<()> {
-        debug!(?request.group_id);
         let update_group = model::groups::ActiveModel {
             group_id: ActiveValue::Set(request.group_id),
             display_name: request
@@ -125,9 +122,8 @@ impl GroupBackendHandler for SqlBackendHandler {
         Ok(())
     }
 
-    #[instrument(skip_all, level = "debug", ret, err)]
+    #[instrument(skip(self), level = "debug", ret, err)]
     async fn create_group(&self, group_name: &str) -> Result<GroupId> {
-        debug!(?group_name);
         let now = chrono::Utc::now().naive_utc();
         let uuid = Uuid::from_name_and_date(group_name, &now);
         let new_group = model::groups::ActiveModel {
@@ -139,9 +135,8 @@ impl GroupBackendHandler for SqlBackendHandler {
         Ok(new_group.insert(&self.sql_pool).await?.group_id)
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip(self), level = "debug", err)]
     async fn delete_group(&self, group_id: GroupId) -> Result<()> {
-        debug!(?group_id);
         let res = model::Group::delete_by_id(group_id)
             .exec(&self.sql_pool)
             .await?;

server/src/domain/sql_opaque_handler.rs

@@ -15,7 +15,7 @@ use tracing::{debug, instrument};
 
 type SqlOpaqueHandler = SqlBackendHandler;
 
-#[instrument(skip_all, level = "debug", err)]
+#[instrument(skip_all, level = "debug", err, fields(username = %username.as_str()))]
 fn passwords_match(
     password_file_bytes: &[u8],
     clear_password: &str,
@@ -49,7 +49,7 @@ impl SqlBackendHandler {
         )?)
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip(self), level = "debug", err)]
     async fn get_password_file_for_user(&self, user_id: UserId) -> Result<Option<Vec<u8>>> {
         // Fetch the previously registered password file from the DB.
         Ok(model::User::find_by_id(user_id)
@@ -201,7 +201,7 @@ impl OpaqueHandler for SqlOpaqueHandler {
 }
 
 /// Convenience function to set a user's password.
-#[instrument(skip_all, level = "debug", err)]
+#[instrument(skip_all, level = "debug", err, fields(username = %username.as_str()))]
 pub(crate) async fn register_password(
     opaque_handler: &SqlOpaqueHandler,
     username: &UserId,

server/src/domain/sql_user_backend_handler.rs

@@ -17,7 +17,7 @@ use sea_orm::{
     QueryFilter, QueryOrder, QuerySelect, QueryTrait, Set, TransactionTrait,
 };
 use std::collections::HashSet;
-use tracing::{debug, instrument};
+use tracing::instrument;
 
 fn attribute_condition(name: String, value: String) -> Cond {
     Expr::in_subquery(
@@ -91,14 +91,13 @@ fn to_value(opt_name: &Option<String>) -> ActiveValue<Option<String>> {
 
 #[async_trait]
 impl UserListerBackendHandler for SqlBackendHandler {
-    #[instrument(skip_all, level = "debug", ret, err)]
+    #[instrument(skip(self), level = "debug", ret, err)]
     async fn list_users(
         &self,
         filters: Option<UserRequestFilter>,
         // To simplify the query, we always fetch groups. TODO: cleanup.
         _get_groups: bool,
     ) -> Result<Vec<UserAndGroups>> {
-        debug!(?filters);
         let results = model::User::find()
             .filter(
                 filters
@@ -172,9 +171,8 @@ impl UserListerBackendHandler for SqlBackendHandler {
 
 #[async_trait]
 impl UserBackendHandler for SqlBackendHandler {
-    #[instrument(skip_all, level = "debug", ret)]
+    #[instrument(skip_all, level = "debug", ret, fields(user_id = ?user_id.as_str()))]
     async fn get_user_details(&self, user_id: &UserId) -> Result<User> {
-        debug!(?user_id);
         let mut user = User::from(
             model::User::find_by_id(user_id.to_owned())
                 .one(&self.sql_pool)
@@ -190,9 +188,8 @@ impl UserBackendHandler for SqlBackendHandler {
         Ok(user)
     }
 
-    #[instrument(skip_all, level = "debug", ret, err)]
+    #[instrument(skip_all, level = "debug", ret, err, fields(user_id = ?user_id.as_str()))]
     async fn get_user_groups(&self, user_id: &UserId) -> Result<HashSet<GroupDetails>> {
-        debug!(?user_id);
         let user = model::User::find_by_id(user_id.to_owned())
             .one(&self.sql_pool)
             .await?
@@ -205,9 +202,8 @@ impl UserBackendHandler for SqlBackendHandler {
         ))
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip(self), level = "debug", err, fields(user_id = ?request.user_id.as_str()))]
     async fn create_user(&self, request: CreateUserRequest) -> Result<()> {
-        debug!(user_id = ?request.user_id);
         let now = chrono::Utc::now().naive_utc();
         let uuid = Uuid::from_name_and_date(request.user_id.as_str(), &now);
         let new_user = model::users::ActiveModel {
@@ -256,9 +252,8 @@ impl UserBackendHandler for SqlBackendHandler {
         Ok(())
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip(self), level = "debug", err, fields(user_id = ?request.user_id.as_str()))]
     async fn update_user(&self, request: UpdateUserRequest) -> Result<()> {
-        debug!(user_id = ?request.user_id);
         let update_user = model::users::ActiveModel {
             user_id: ActiveValue::Set(request.user_id.clone()),
             email: request.email.map(ActiveValue::Set).unwrap_or_default(),
@@ -329,9 +324,8 @@ impl UserBackendHandler for SqlBackendHandler {
         Ok(())
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip_all, level = "debug", err, fields(user_id = ?user_id.as_str()))]
     async fn delete_user(&self, user_id: &UserId) -> Result<()> {
-        debug!(?user_id);
         let res = model::User::delete_by_id(user_id.clone())
             .exec(&self.sql_pool)
             .await?;
@@ -344,9 +338,8 @@ impl UserBackendHandler for SqlBackendHandler {
         Ok(())
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip_all, level = "debug", err, fields(user_id = ?user_id.as_str(), group_id))]
     async fn add_user_to_group(&self, user_id: &UserId, group_id: GroupId) -> Result<()> {
-        debug!(?user_id, ?group_id);
         let new_membership = model::memberships::ActiveModel {
             user_id: ActiveValue::Set(user_id.clone()),
             group_id: ActiveValue::Set(group_id),
@@ -355,9 +348,8 @@ impl UserBackendHandler for SqlBackendHandler {
         Ok(())
     }
 
-    #[instrument(skip_all, level = "debug", err)]
+    #[instrument(skip_all, level = "debug", err, fields(user_id = ?user_id.as_str(), group_id))]
     async fn remove_user_from_group(&self, user_id: &UserId, group_id: GroupId) -> Result<()> {
-        debug!(?user_id, ?group_id);
         let res = model::Membership::delete_by_id((user_id.clone(), group_id))
             .exec(&self.sql_pool)
             .await?;

server/src/infra/auth_service.rs

@@ -423,7 +423,7 @@ where
         .unwrap_or_else(error_to_http_response)
 }
 
-#[instrument(skip_all, level = "debug")]
+#[instrument(skip_all, level = "debug", fields(name = %request.name))]
 async fn post_authorize<Backend>(
     data: web::Data<AppState<Backend>>,
     request: web::Json<BindRequest>,
@@ -432,7 +432,6 @@ where
     Backend: TcpBackendHandler + BackendHandler + LoginHandler + 'static,
 {
     let name = request.name.clone();
-    debug!(%name);
     data.get_login_handler().bind(request.into_inner()).await?;
     get_login_successful_response(&data, &name).await
 }

server/src/infra/db_cleaner.rs

@@ -48,7 +48,6 @@ impl Scheduler {
 
     #[instrument(skip_all)]
     async fn cleanup_db(sql_pool: DbConnection) {
-        info!("Cleaning DB");
         if let Err(e) = model::JwtRefreshStorage::delete_many()
             .filter(JwtRefreshStorageColumn::ExpiryDate.lt(chrono::Utc::now().naive_utc()))
             .exec(&sql_pool)
@@ -70,7 +69,6 @@ impl Scheduler {
         {
             error!("DB error while cleaning up password reset tokens: {}", e);
         };
-        info!("DB cleaned!");
     }
 
     fn duration_until_next(&self) -> Duration {

server/src/infra/healthcheck.rs

@@ -69,7 +69,7 @@ where
     Ok(())
 }
 
-#[instrument(skip_all, level = "info", err)]
+#[instrument(level = "info", err)]
 pub async fn check_ldap(port: u16) -> Result<()> {
     check_ldap_endpoint(TcpStream::connect(format!("localhost:{}", port)).await?).await
 }
@@ -126,7 +126,7 @@ fn get_tls_connector(ldaps_options: &LdapsOptions) -> Result<RustlsTlsConnector>
     Ok(std::sync::Arc::new(client_config).into())
 }
 
-#[instrument(skip_all, level = "info", err)]
+#[instrument(skip_all, level = "info", err, fields(port = %ldaps_options.port))]
 pub async fn check_ldaps(ldaps_options: &LdapsOptions) -> Result<()> {
     if !ldaps_options.enabled {
         info!("LDAPS not enabled");
@@ -150,7 +150,7 @@ pub async fn check_ldaps(ldaps_options: &LdapsOptions) -> Result<()> {
     .await
 }
 
-#[instrument(skip_all, level = "info", err)]
+#[instrument(level = "info", err)]
 pub async fn check_api(port: u16) -> Result<()> {
     reqwest::get(format!("http://localhost:{}/health", port))
         .await?

server/src/infra/ldap_handler.rs

@@ -243,9 +243,8 @@ impl<Backend: BackendHandler + LoginHandler + OpaqueHandler> LdapHandler<Backend
         )
     }
 
-    #[instrument(skip_all, level = "debug")]
+    #[instrument(skip_all, level = "debug", fields(dn = %request.dn))]
     pub async fn do_bind(&mut self, request: &LdapBindRequest) -> (LdapResultCode, String) {
-        debug!("DN: {}", &request.dn);
         let user_id = match get_user_id_from_distinguished_name(
             &request.dn.to_ascii_lowercase(),
             &self.ldap_info.base_dn,

server/src/infra/logging.rs

@@ -3,8 +3,8 @@ use actix_web::{
     dev::{ServiceRequest, ServiceResponse},
     Error,
 };
-use tracing::{error, info, Span};
-use tracing_actix_web::{root_span, RootSpanBuilder};
+use tracing::{debug, error, Span};
+use tracing_actix_web::RootSpanBuilder;
 use tracing_subscriber::{filter::EnvFilter, layer::SubscriberExt, util::SubscriberInitExt};
 
 /// We will define a custom root span builder to capture additional fields, specific
@@ -13,11 +13,11 @@ pub struct CustomRootSpanBuilder;
 
 impl RootSpanBuilder for CustomRootSpanBuilder {
     fn on_request_start(request: &ServiceRequest) -> Span {
-        let span = root_span!(request);
-        span.in_scope(|| {
-            info!(uri = %request.uri());
-        });
-        span
+        tracing::debug_span!(
+            "HTTP request",
+            method = request.method().to_string(),
+            uri = request.uri().to_string()
+        )
     }
 
     fn on_request_end<B>(_: Span, outcome: &Result<ServiceResponse<B>, Error>) {
@@ -26,7 +26,7 @@ impl RootSpanBuilder for CustomRootSpanBuilder {
                 if let Some(error) = response.response().error() {
                     error!(?error);
                 } else {
-                    info!(status_code = &response.response().status().as_u16());
+                    debug!(status_code = &response.response().status().as_u16());
                 }
             }
             Err(error) => error!(?error),