diff --git a/Cargo.lock b/Cargo.lock index d7e91b6..cc299ca 100644 --- a/Cargo.lock +++ b/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", diff --git a/Cargo.toml b/Cargo.toml index 4cf17a3..d6e07fc 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,6 +9,8 @@ members = [ default-members = ["server"] +resolver = "2" + [profile.release] lto = true diff --git a/server/Cargo.toml b/server/Cargo.toml index 1691208..efff0f7 100644 --- a/server/Cargo.toml +++ b/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"] diff --git a/server/src/domain/ldap/group.rs b/server/src/domain/ldap/group.rs index 2d4294c..d4df918 100644 --- a/server/src/domain/ldap/group.rs +++ b/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( ldap_info: &LdapInfo, ldap_filter: &LdapFilter, base: &str, backend: &Backend, ) -> LdapResult> { - debug!(?ldap_filter); let filters = convert_group_filter(ldap_info, ldap_filter)?; debug!(?filters); backend diff --git a/server/src/domain/ldap/user.rs b/server/src/domain/ldap/user.rs index 908a5d0..5841cde 100644 --- a/server/src/domain/ldap/user.rs +++ b/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( ldap_info: &LdapInfo, ldap_filter: &LdapFilter, @@ -238,7 +238,6 @@ pub async fn get_user_list( base: &str, backend: &Backend, ) -> LdapResult> { - debug!(?ldap_filter); let filters = convert_user_filter(ldap_info, ldap_filter)?; debug!(?filters); backend diff --git a/server/src/domain/ldap/utils.rs b/server/src/domain/ldap/utils.rs index ade2e1f..24b3db3 100644 --- a/server/src/domain/ldap/utils.rs +++ b/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 } diff --git a/server/src/domain/sql_group_backend_handler.rs b/server/src/domain/sql_group_backend_handler.rs index 6ab2cb3..eb24635 100644 --- a/server/src/domain/sql_group_backend_handler.rs +++ b/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) -> Result> { - 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 { - debug!(?group_id); model::Group::find_by_id(group_id) .into_model::() .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 { - 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?; diff --git a/server/src/domain/sql_opaque_handler.rs b/server/src/domain/sql_opaque_handler.rs index a287c12..9bda7e6 100644 --- a/server/src/domain/sql_opaque_handler.rs +++ b/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>> { // 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, diff --git a/server/src/domain/sql_user_backend_handler.rs b/server/src/domain/sql_user_backend_handler.rs index 7b3e663..2af38f1 100644 --- a/server/src/domain/sql_user_backend_handler.rs +++ b/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) -> ActiveValue> { #[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, // To simplify the query, we always fetch groups. TODO: cleanup. _get_groups: bool, ) -> Result> { - 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 { - 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> { - 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?; diff --git a/server/src/infra/auth_service.rs b/server/src/infra/auth_service.rs index 4f7581b..7dea093 100644 --- a/server/src/infra/auth_service.rs +++ b/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( data: web::Data>, request: web::Json, @@ -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 } diff --git a/server/src/infra/db_cleaner.rs b/server/src/infra/db_cleaner.rs index 9e87bde..3dd772e 100644 --- a/server/src/infra/db_cleaner.rs +++ b/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 { diff --git a/server/src/infra/healthcheck.rs b/server/src/infra/healthcheck.rs index 55f00c6..1be251f 100644 --- a/server/src/infra/healthcheck.rs +++ b/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 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? diff --git a/server/src/infra/ldap_handler.rs b/server/src/infra/ldap_handler.rs index dbb141f..cd19d47 100644 --- a/server/src/infra/ldap_handler.rs +++ b/server/src/infra/ldap_handler.rs @@ -243,9 +243,8 @@ impl LdapHandler (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, diff --git a/server/src/infra/logging.rs b/server/src/infra/logging.rs index eaaa80b..a6a68f1 100644 --- a/server/src/infra/logging.rs +++ b/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(_: Span, outcome: &Result, 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),