diff --git a/crates/cli/src/commands/config.rs b/crates/cli/src/commands/config.rs index a1d6376e..f8e3aaa5 100644 --- a/crates/cli/src/commands/config.rs +++ b/crates/cli/src/commands/config.rs @@ -15,7 +15,7 @@ use clap::Parser; use mas_config::{ConfigurationSection, RootConfig}; use rand::SeedableRng; -use tracing::info; +use tracing::{info, info_span}; #[derive(Parser, Debug)] pub(super) struct Options { @@ -40,6 +40,8 @@ impl Options { use Subcommand as SC; match &self.subcommand { SC::Dump => { + let _span = info_span!("cli.config.dump").entered(); + let config: RootConfig = root.load_config()?; serde_yaml::to_writer(std::io::stdout(), &config)?; @@ -47,11 +49,15 @@ impl Options { Ok(()) } SC::Check => { + let _span = info_span!("cli.config.check").entered(); + let _config: RootConfig = root.load_config()?; info!(path = ?root.config, "Configuration file looks good"); Ok(()) } SC::Generate => { + let _span = info_span!("cli.config.generate").entered(); + // XXX: we should disallow SeedableRng::from_entropy let rng = rand_chacha::ChaChaRng::from_entropy(); let config = RootConfig::load_and_generate(rng).await?; diff --git a/crates/cli/src/commands/database.rs b/crates/cli/src/commands/database.rs index 338fdbf9..ca59ce1d 100644 --- a/crates/cli/src/commands/database.rs +++ b/crates/cli/src/commands/database.rs @@ -16,6 +16,7 @@ use anyhow::Context; use clap::Parser; use mas_config::DatabaseConfig; use mas_storage::MIGRATOR; +use tracing::{info_span, Instrument}; use crate::util::database_from_config; @@ -33,12 +34,14 @@ enum Subcommand { impl Options { pub async fn run(&self, root: &super::Options) -> anyhow::Result<()> { + let _span = info_span!("cli.database.migrate").entered(); let config: DatabaseConfig = root.load_config()?; let pool = database_from_config(&config).await?; // Run pending migrations MIGRATOR .run(&pool) + .instrument(info_span!("db.migrate")) .await .context("could not run migrations")?; diff --git a/crates/cli/src/commands/debug.rs b/crates/cli/src/commands/debug.rs index 7b2d6cd8..24f9262c 100644 --- a/crates/cli/src/commands/debug.rs +++ b/crates/cli/src/commands/debug.rs @@ -19,7 +19,7 @@ use mas_handlers::HttpClientFactory; use mas_http::HttpServiceExt; use tokio::io::AsyncWriteExt; use tower::{Service, ServiceExt}; -use tracing::info; +use tracing::{info, info_span}; use crate::util::policy_factory_from_config; @@ -74,6 +74,7 @@ impl Options { json: false, url, } => { + let _span = info_span!("cli.debug.http").entered(); let mut client = http_client_factory.client("cli-debug-http").await?; let request = hyper::Request::builder() .uri(url) @@ -98,6 +99,7 @@ impl Options { json: true, url, } => { + let _span = info_span!("cli.debug.http").entered(); let mut client = http_client_factory .client("cli-debug-http") .await? @@ -122,6 +124,7 @@ impl Options { } SC::Policy => { + let _span = info_span!("cli.debug.policy").entered(); let config: PolicyConfig = root.load_config()?; info!("Loading and compiling the policy module"); let policy_factory = policy_factory_from_config(&config).await?; diff --git a/crates/cli/src/commands/manage.rs b/crates/cli/src/commands/manage.rs index 9e2b3988..62d62db8 100644 --- a/crates/cli/src/commands/manage.rs +++ b/crates/cli/src/commands/manage.rs @@ -25,7 +25,7 @@ use mas_storage::{ }; use oauth2_types::scope::Scope; use rand::SeedableRng; -use tracing::{info, warn}; +use tracing::{info, info_span, warn}; use crate::util::{database_from_config, password_manager_from_config}; @@ -193,6 +193,9 @@ impl Options { match &self.subcommand { SC::SetPassword { username, password } => { + let _span = + info_span!("cli.manage.set_password", user.username = %username).entered(); + let database_config: DatabaseConfig = root.load_config()?; let passwords_config: PasswordsConfig = root.load_config()?; @@ -221,6 +224,13 @@ impl Options { } SC::VerifyEmail { username, email } => { + let _span = info_span!( + "cli.manage.verify_email", + user.username = username, + user_email.email = email + ) + .entered(); + let config: DatabaseConfig = root.load_config()?; let pool = database_from_config(&config).await?; let mut txn = pool.begin().await?; @@ -245,6 +255,8 @@ impl Options { } SC::ImportClients { update } => { + let _span = info_span!("cli.manage.import_clients").entered(); + let config: RootConfig = root.load_config()?; let pool = database_from_config(&config.database).await?; let encrypter = config.secrets.encrypter(); @@ -303,6 +315,13 @@ impl Options { client_secret, signing_alg, } => { + let _span = info_span!( + "cli.manage.add_oauth_upstream", + upstream_oauth_provider.issuer = issuer, + upstream_oauth_provider.client_id = client_id, + ) + .entered(); + let config: RootConfig = root.load_config()?; let encrypter = config.secrets.encrypter(); let pool = database_from_config(&config.database).await?; diff --git a/crates/cli/src/commands/server.rs b/crates/cli/src/commands/server.rs index 60654782..fb2a3f16 100644 --- a/crates/cli/src/commands/server.rs +++ b/crates/cli/src/commands/server.rs @@ -24,7 +24,7 @@ use mas_router::UrlBuilder; use mas_storage::MIGRATOR; use mas_tasks::TaskQueue; use tokio::signal::unix::SignalKind; -use tracing::{info, warn}; +use tracing::{info, info_span, warn, Instrument}; use crate::util::{ database_from_config, mailer_from_config, password_manager_from_config, @@ -45,6 +45,7 @@ pub(super) struct Options { impl Options { #[allow(clippy::too_many_lines)] pub async fn run(&self, root: &super::Options) -> anyhow::Result<()> { + let span = info_span!("cli.run.init").entered(); let config: RootConfig = root.load_config()?; // Connect to the database @@ -55,6 +56,7 @@ impl Options { info!("Running pending migrations"); MIGRATOR .run(&pool) + .instrument(info_span!("db.migrate")) .await .context("could not run migrations")?; } @@ -186,6 +188,8 @@ impl Options { .with_signal(SignalKind::terminate())? .with_signal(SignalKind::interrupt())?; + span.exit(); + mas_listener::server::run_servers(servers, shutdown).await; Ok(()) diff --git a/crates/cli/src/commands/templates.rs b/crates/cli/src/commands/templates.rs index 186a097e..a3a1bf9c 100644 --- a/crates/cli/src/commands/templates.rs +++ b/crates/cli/src/commands/templates.rs @@ -17,6 +17,7 @@ use clap::Parser; use mas_storage::Clock; use mas_templates::Templates; use rand::SeedableRng; +use tracing::info_span; #[derive(Parser, Debug)] pub(super) struct Options { @@ -38,6 +39,8 @@ impl Options { use Subcommand as SC; match &self.subcommand { SC::Check { path } => { + let _span = info_span!("cli.templates.check").entered(); + let clock = Clock::default(); // XXX: we should disallow SeedableRng::from_entropy let mut rng = rand_chacha::ChaChaRng::from_entropy(); diff --git a/crates/cli/src/util.rs b/crates/cli/src/util.rs index ec525478..b6485e95 100644 --- a/crates/cli/src/util.rs +++ b/crates/cli/src/util.rs @@ -110,6 +110,7 @@ pub async fn templates_from_config( Templates::load(config.path.clone(), url_builder.clone()).await } +#[tracing::instrument(name = "db.connect", skip_all, err(Debug))] pub async fn database_from_config(config: &DatabaseConfig) -> Result { let mut options = match &config.options { DatabaseConnectConfig::Uri { uri } => uri diff --git a/crates/config/src/sections/secrets.rs b/crates/config/src/sections/secrets.rs index 3a0f79a4..afe624f4 100644 --- a/crates/config/src/sections/secrets.rs +++ b/crates/config/src/sections/secrets.rs @@ -86,6 +86,7 @@ impl SecretsConfig { /// # Errors /// /// Returns an error when a key could not be imported + #[tracing::instrument(name = "secrets.load", skip_all, err(Debug))] pub async fn key_store(&self) -> anyhow::Result { let mut keys = Vec::with_capacity(self.keys.len()); for item in &self.keys { diff --git a/crates/email/src/mailer.rs b/crates/email/src/mailer.rs index 177cc8d1..979a9f7b 100644 --- a/crates/email/src/mailer.rs +++ b/crates/email/src/mailer.rs @@ -100,10 +100,10 @@ impl Mailer { /// /// Will return `Err` if the email failed rendering or failed sending #[tracing::instrument( + name = "email.verification.send", skip_all, fields( email.to = %to, - email.from = %self.from, user.id = %context.user().id, user_email_verification.id = %context.verification().id, user_email_verification.code = context.verification().code, @@ -125,6 +125,7 @@ impl Mailer { /// # Errors /// /// Returns an error if the connection failed + #[tracing::instrument(name = "email.test_connection", skip_all, err)] pub async fn test_connection(&self) -> Result<(), crate::transport::Error> { self.transport.test_connection().await } diff --git a/crates/handlers/src/passwords.rs b/crates/handlers/src/passwords.rs index 89326c9a..4be71a45 100644 --- a/crates/handlers/src/passwords.rs +++ b/crates/handlers/src/passwords.rs @@ -71,7 +71,7 @@ impl PasswordManager { /// # Errors /// /// Returns an error if the hashing failed - #[tracing::instrument(skip_all)] + #[tracing::instrument(name = "passwords.hash", skip_all)] pub async fn hash( &self, rng: R, @@ -82,13 +82,16 @@ impl PasswordManager { let rng = rand_chacha::ChaChaRng::from_rng(rng)?; let hashers = self.hashers.clone(); let default_hasher_version = self.default_hasher; + let span = tracing::Span::current(); let hashed = tokio::task::spawn_blocking(move || { - let default_hasher = hashers - .get(&default_hasher_version) - .context("Default hasher not found")?; + span.in_scope(move || { + let default_hasher = hashers + .get(&default_hasher_version) + .context("Default hasher not found")?; - default_hasher.hash_blocking(rng, &password) + default_hasher.hash_blocking(rng, &password) + }) }) .await??; @@ -100,7 +103,7 @@ impl PasswordManager { /// # Errors /// /// Returns an error if the password hash verification failed - #[tracing::instrument(skip_all, fields(%scheme))] + #[tracing::instrument(name = "passwords.verify", skip_all, fields(%scheme))] pub async fn verify( &self, scheme: SchemeVersion, @@ -108,10 +111,13 @@ impl PasswordManager { hashed_password: String, ) -> Result<(), anyhow::Error> { let hashers = self.hashers.clone(); + let span = tracing::Span::current(); tokio::task::spawn_blocking(move || { - let hasher = hashers.get(&scheme).context("Hashing scheme not found")?; - hasher.verify_blocking(&hashed_password, &password) + span.in_scope(move || { + let hasher = hashers.get(&scheme).context("Hashing scheme not found")?; + hasher.verify_blocking(&hashed_password, &password) + }) }) .await??; @@ -124,7 +130,7 @@ impl PasswordManager { /// # Errors /// /// Returns an error if the password hash verification failed - #[tracing::instrument(skip_all, fields(%scheme))] + #[tracing::instrument(name = "passwords.verify_and_upgrade", skip_all, fields(%scheme))] pub async fn verify_and_upgrade( &self, rng: R, diff --git a/crates/policy/src/lib.rs b/crates/policy/src/lib.rs index 27cfb1b3..d895339a 100644 --- a/crates/policy/src/lib.rs +++ b/crates/policy/src/lib.rs @@ -69,7 +69,7 @@ pub struct PolicyFactory { } impl PolicyFactory { - #[tracing::instrument(skip(source), err)] + #[tracing::instrument(name = "policy.load", skip(source), err)] pub async fn load( mut source: impl AsyncRead + std::marker::Unpin, data: serde_json::Value, @@ -108,7 +108,7 @@ impl PolicyFactory { authorization_grant_endpoint, }; - // Try to instanciate + // Try to instantiate factory .instantiate() .await @@ -117,7 +117,7 @@ impl PolicyFactory { Ok(factory) } - #[tracing::instrument(skip(self), err)] + #[tracing::instrument(name = "policy.instantiate", skip_all, err)] pub async fn instantiate(&self) -> Result { let mut store = Store::new(&self.engine, ()); let runtime = Runtime::new(&mut store, &self.module) @@ -189,7 +189,14 @@ pub enum EvaluationError { } impl Policy { - #[tracing::instrument(skip(self, password))] + #[tracing::instrument( + name = "policy.evaluate.register", + skip_all, + fields( + data.username = username, + ), + err, + )] pub async fn evaluate_register( &mut self, username: &str, @@ -234,7 +241,15 @@ impl Policy { Ok(res) } - #[tracing::instrument(skip(self))] + #[tracing::instrument( + name = "policy.evaluate.authorization_grant", + skip_all, + fields( + data.authorization_grant.id = %authorization_grant.id, + data.user.id = %user.id, + ), + err, + )] pub async fn evaluate_authorization_grant( &mut self, authorization_grant: &AuthorizationGrant, diff --git a/crates/templates/src/lib.rs b/crates/templates/src/lib.rs index 496bcc26..938a701a 100644 --- a/crates/templates/src/lib.rs +++ b/crates/templates/src/lib.rs @@ -96,6 +96,12 @@ impl Templates { } /// Load the templates from the given config + #[tracing::instrument( + name = "templates.load", + skip_all, + fields(%path), + err, + )] pub async fn load( path: Utf8PathBuf, url_builder: UrlBuilder, @@ -110,14 +116,17 @@ impl Templates { async fn load_(path: &Utf8Path, url_builder: UrlBuilder) -> Result { let path = path.to_owned(); + let span = tracing::Span::current(); // This uses blocking I/Os, do that in a blocking task let mut tera = tokio::task::spawn_blocking(move || { - let path = path.canonicalize_utf8()?; - let path = format!("{path}/**/*.{{html,txt,subject}}"); + span.in_scope(move || { + let path = path.canonicalize_utf8()?; + let path = format!("{path}/**/*.{{html,txt,subject}}"); - info!(%path, "Loading templates from filesystem"); - Tera::new(&path) + info!(%path, "Loading templates from filesystem"); + Tera::new(&path) + }) }) .await??; @@ -138,7 +147,13 @@ impl Templates { } /// Reload the templates on disk - pub async fn reload(&self) -> anyhow::Result<()> { + #[tracing::instrument( + name = "templates.reload", + skip_all, + fields(path = %self.path), + err, + )] + pub async fn reload(&self) -> Result<(), TemplateLoadingError> { // Prepare the new Tera instance let new_tera = Self::load_(&self.path, self.url_builder.clone()).await?;