Better tracing spans

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

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

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

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

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

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

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<PgPool, anyhow::Error> {
     let mut options = match &config.options {
         DatabaseConnectConfig::Uri { uri } => uri

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<Keystore> {
         let mut keys = Vec::with_capacity(self.keys.len());
         for item in &self.keys {

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
     }

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<R: CryptoRng + RngCore + Send>(
         &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
+            span.in_scope(move || {
-                .get(&default_hasher_version)
+                let default_hasher = hashers
-                .context("Default hasher not found")?;
+                    .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")?;
+            span.in_scope(move || {
-            hasher.verify_blocking(&hashed_password, &password)
+                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<R: CryptoRng + RngCore + Send>(
         &self,
         rng: R,

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<Policy, InstanciateError> {
         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,

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<Tera, TemplateLoadingError> {
         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()?;
+            span.in_scope(move || {
-            let path = format!("{path}/**/*.{{html,txt,subject}}");
+                let path = path.canonicalize_utf8()?;
+                let path = format!("{path}/**/*.{{html,txt,subject}}");
 
-            info!(%path, "Loading templates from filesystem");
+                info!(%path, "Loading templates from filesystem");
-            Tera::new(&path)
+                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?;