Adopt Tracing

Cargo.toml

@@ -42,4 +42,6 @@ members = [
   "examples/tls",
   "examples/fairings",
   "examples/hello_2018",
-]
+  "examples/trace_env_logger",
+  "examples/trace_subscriber",
+]

contrib/lib/Cargo.toml

@@ -45,7 +45,7 @@ memcache_pool = ["databases", "memcache", "r2d2-memcache"]
 tokio = { version = "0.2.0", optional = true }
 rocket_contrib_codegen = { version = "0.5.0-dev", path = "../codegen", optional = true }
 rocket = { version = "0.5.0-dev", path = "../../core/lib/", default-features = false }
-log = "0.4"
+tracing = { version = "0.1", default-features = false }
 
 # Serialization and templating dependencies.
 serde = { version = "1.0", optional = true }

contrib/lib/src/compression/fairing.rs

@@ -115,17 +115,17 @@ impl Fairing for Compression {
                         if let Value::String(s) = ex {
                             let mt = MediaType::parse_flexible(s);
                             if mt.is_none() {
-                                warn_!("Ignoring invalid media type '{:?}'", s);
+                                warn!("Ignoring invalid media type '{:?}'", s);
                             }
                             mt
                         } else {
-                            warn_!("Ignoring non-string media type '{:?}'", ex);
+                            warn!("Ignoring non-string media type '{:?}'", ex);
                             None
                         }
                     }).collect();
                 }
                 None => {
-                    warn_!(
+                    warn!(
                         "Exclusions is not an array; using default compression exclusions '{:?}'",
                         ctxt.exclusions
                     );
@@ -134,7 +134,7 @@ impl Fairing for Compression {
             Err(ConfigError::Missing(_)) => { /* ignore missing */ }
             Err(e) => {
                 e.pretty_print();
-                warn_!(
+                warn!(
                     "Using default compression exclusions '{:?}'",
                     ctxt.exclusions
                 );

contrib/lib/src/databases.rs

@@ -377,6 +377,7 @@ use rocket::http::Status;
 
 use rocket::tokio::sync::{OwnedSemaphorePermit, Semaphore, Mutex};
 use rocket::tokio::time::timeout;
+use rocket::trace::prelude::*;
 
 use self::r2d2::ManageConnection;
 
@@ -738,7 +739,8 @@ pub struct Connection<K, C: Poolable> {
 async fn run_blocking<F, R>(job: F) -> R
     where F: FnOnce() -> R + Send + 'static, R: Send + 'static,
 {
-    match tokio::task::spawn_blocking(job).await {
+    let span = tracing::Span::current();
+    match tokio::task::spawn_blocking(move || span.in_scope(|| job())).await {
         Ok(ret) => ret,
         Err(e) => match e.try_into_panic() {
             Ok(panic) => std::panic::resume_unwind(panic),
@@ -748,9 +750,10 @@ async fn run_blocking<F, R>(job: F) -> R
 }
 
 macro_rules! dberr {
-    ($msg:literal, $db_name:expr, $efmt:literal, $error:expr, $rocket:expr) => ({
-        rocket::error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);
-        error_!($efmt, $error);
+    ($target:literal, $msg:literal, $db_name:expr, $efmt:literal, $error:expr, $rocket:expr) => ({
+        rocket::trace::error_span!($target, "database {} error for pool named `{}`", $msg, $db_name).in_scope(|| {
+            rocket::trace::error!($efmt, $error);
+        });
         return Err($rocket);
     });
 }
@@ -760,7 +763,7 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
         AdHoc::on_attach(fairing_name, move |rocket| async move {
             let config = match Config::from(db, &rocket) {
                 Ok(config) => config,
-                Err(e) => dberr!("config", db, "{}", e, rocket),
+                Err(e) => dberr!("config_error", "config", db, "{}", e, rocket),
             };
 
             let pool_size = config.pool_size;
@@ -770,9 +773,9 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
                     semaphore: Arc::new(Semaphore::new(pool_size as usize)),
                     _marker: PhantomData,
                 })),
-                Err(Error::Config(e)) => dberr!("config", db, "{}", e, rocket),
-                Err(Error::Pool(e)) => dberr!("pool init", db, "{}", e, rocket),
-                Err(Error::Custom(e)) => dberr!("pool manager", db, "{:?}", e, rocket),
+                Err(Error::Config(e)) => dberr!("config_error", "config", db, "{}", e, rocket),
+                Err(Error::Pool(e)) => dberr!("init_error", "pool init", db, "{}", e, rocket),
+                Err(Error::Custom(e)) => dberr!("init_error", "pool manager", db, "{:?}", e, rocket),
             }
         })
     }
@@ -782,7 +785,7 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
         let permit = match timeout(duration, self.semaphore.clone().acquire_owned()).await {
             Ok(p) => p,
             Err(_) => {
-                error_!("database connection retrieval timed out");
+                error!("database connection retrieval timed out");
                 return Err(());
             }
         };
@@ -795,7 +798,7 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
                 _marker: PhantomData,
             }),
             Err(e) => {
-                error_!("failed to get a database connection: {}", e);
+                error!("failed to get a database connection: {}", e);
                 Err(())
             }
         }
@@ -836,16 +839,17 @@ impl<K, C: Poolable> Drop for Connection<K, C> {
         let permit = self.permit.take();
         tokio::spawn(async move {
             let mut connection = connection.lock_owned().await;
-            tokio::task::spawn_blocking(move || {
+            let span = tracing::Span::current();
+            tokio::task::spawn_blocking(move || span.in_scope(|| {
                 if let Some(conn) = connection.take() {
                     drop(conn);
                 }
 
                 // Explicitly dropping the permit here so that it's only
                 // released after the connection is.
                 drop(permit);
-            })
-        });
+            }));
+        }.in_current_span());
     }
 }
 
@@ -858,7 +862,7 @@ impl<'a, 'r, K: 'static, C: Poolable> FromRequest<'a, 'r> for Connection<K, C> {
         match request.managed_state::<ConnectionPool<K, C>>() {
             Some(c) => c.get().await.into_outcome(Status::ServiceUnavailable),
             None => {
-                error_!("Missing database fairing for `{}`", std::any::type_name::<K>());
+                error!("Missing database fairing for `{}`", std::any::type_name::<K>());
                 Outcome::Failure((Status::InternalServerError, ()))
             }
         }

contrib/lib/src/helmet/helmet.rs

@@ -171,8 +171,10 @@ impl SpaceHelmet {
         for policy in self.policies.values() {
             let name = policy.name();
             if response.headers().contains(name.as_str()) {
-                warn!("Space Helmet: response contains a '{}' header.", name);
-                warn_!("Refusing to overwrite existing header.");
+                warn_span!(
+                    "Space Helmet: response contains already contains this header",
+                    header = %name,
+                ).in_scope(|| warn!("Refusing to overwrite existing header."));
                 continue
             }
 
@@ -206,9 +208,10 @@ impl Fairing for SpaceHelmet {
             && rocket.figment().profile() != rocket::Config::DEBUG_PROFILE
             && !self.is_enabled::<Hsts>()
         {
-            warn_!("Space Helmet: deploying with TLS without enabling HSTS.");
-            warn_!("Enabling default HSTS policy.");
-            info_!("To disable this warning, configure an HSTS policy.");
+            warn_span!("Space Helmet: deploying with TLS without enabling HSTS.").in_scope(|| {
+                warn!("Enabling default HSTS policy.");
+                info!("To disable this warning, configure an HSTS policy.");
+            });
             self.force_hsts.store(true, Ordering::Relaxed);
         }
     }

contrib/lib/src/json.rs

@@ -147,7 +147,7 @@ impl<'a, T: Deserialize<'a>> FromTransformedData<'a> for Json<T> {
             match serde_json::from_str(&string) {
                 Ok(v) => Success(Json(v)),
                 Err(e) => {
-                    error_!("Couldn't parse JSON body: {:?}", e);
+                    error!("Couldn't parse JSON body: {:?}", e);
                     if e.is_data() {
                         Failure((Status::UnprocessableEntity, JsonError::Parse(string, e)))
                     } else {
@@ -166,7 +166,7 @@ impl<'r, T: Serialize> Responder<'r, 'static> for Json<T> {
     fn respond_to(self, req: &'r Request<'_>) -> response::Result<'static> {
         let string = serde_json::to_string(&self.0)
             .map_err(|e| {
-                error_!("JSON failed to serialize: {:?}", e);
+                error!("JSON failed to serialize: {:?}", e);
                 Status::InternalServerError
             })?;
 

contrib/lib/src/lib.rs

@@ -40,7 +40,7 @@
 //! This crate is expected to grow with time, bringing in outside crates to be
 //! officially supported by Rocket.
 
-#[allow(unused_imports)] #[macro_use] extern crate log;
+#[allow(unused_imports)] #[macro_use] extern crate tracing;
 #[allow(unused_imports)] #[macro_use] extern crate rocket;
 
 #[cfg(feature="json")] #[macro_use] pub mod json;

contrib/lib/src/msgpack.rs

@@ -138,7 +138,7 @@ impl<'a, T: Deserialize<'a>> FromTransformedData<'a> for MsgPack<T> {
             match rmp_serde::from_slice(&buf) {
                 Ok(val) => Success(MsgPack(val)),
                 Err(e) => {
-                    error_!("Couldn't parse MessagePack body: {:?}", e);
+                    error!("Couldn't parse MessagePack body: {:?}", e);
                     match e {
                         TypeMismatch(_) | OutOfRange | LengthMismatch(_) => {
                             Failure((Status::UnprocessableEntity, e))
@@ -158,7 +158,7 @@ impl<'r, T: Serialize> Responder<'r, 'static> for MsgPack<T> {
     fn respond_to(self, req: &'r Request<'_>) -> response::Result<'static> {
         let buf = rmp_serde::to_vec(&self.0)
             .map_err(|e| {
-                error_!("MsgPack failed to serialize: {:?}", e);
+                error!("MsgPack failed to serialize: {:?}", e);
                 Status::InternalServerError
             })?;
 

contrib/lib/src/serve.rs

@@ -288,9 +288,10 @@ impl StaticFiles {
 
         let path = path.as_ref();
         if !path.is_dir() {
-            error!("`StaticFiles` supplied with invalid path");
-            info_!("'{}' is not a directory", Paint::white(path.display()));
-            panic!("refusing to continue due to invalid static files path");
+            error_span!("`StaticFiles` supplied with invalid path").in_scope(|| {
+                info!(path = %Paint::white(path.display()), "Path is not a directory");
+                panic!("refusing to continue due to invalid static files path");
+            });
         }
 
         StaticFiles { root: path.into(), options, rank: Self::DEFAULT_RANK }

contrib/lib/src/templates/context.rs

@@ -28,10 +28,11 @@ impl Context {
             for path in glob::glob(glob_path).unwrap().filter_map(Result::ok) {
                 let (name, data_type_str) = split_path(&root, &path);
                 if let Some(info) = templates.get(&*name) {
-                    warn_!("Template name '{}' does not have a unique path.", name);
-                    info_!("Existing path: {:?}", info.path);
-                    info_!("Additional path: {:?}", path);
-                    warn_!("Using existing path for template '{}'.", name);
+                    warn_span!("invalid_template_path", "Template name '{}' does not have a unique path.", name).in_scope(|| {
+                        info!(path = ?info.path, "Existing");
+                        info!(path = ?path, "Additiona");
+                        warn!("Using existing path for template '{}'.", name);
+                    });
                     continue;
                 }
 

contrib/lib/src/templates/fairing.rs

@@ -62,10 +62,11 @@ mod context {
 
             let watcher = match watcher {
                 Ok(watcher) => Some(Mutex::new((watcher, rx))),
-                Err(e) => {
-                    warn!("Failed to enable live template reloading: {}", e);
-                    debug_!("Reload error: {:?}", e);
-                    warn_!("Live template reloading is unavailable.");
+                Err(error) => {
+                    warn_span!("Failed to enable live template reloading", %error).in_scope(|| {
+                        debug!(reload_error = ?error);
+                        warn!("Live template reloading is unavailable.");
+                    });
                     None
                 }
             };
@@ -101,21 +102,24 @@ mod context {
                 }
 
                 if changed {
-                    info_!("Change detected: reloading templates.");
-                    let mut ctxt = self.context_mut();
-                    if let Some(mut new_ctxt) = Context::initialize(ctxt.root.clone()) {
-                        match callback(&mut new_ctxt.engines) {
-                            Ok(()) => *ctxt = new_ctxt,
-                            Err(e) => {
-                                warn_!("The template customization callback returned an error:");
-                                warn_!("{}", e);
-                                warn_!("The existing templates will remain active.");
+                    info_span!("Change detected: reloading templates.").in_scope(|| {
+                        let mut ctxt = self.context_mut();
+                        if let Some(mut new_ctxt) = Context::initialize(ctxt.root.clone()) {
+                            match callback(&mut new_ctxt.engines) {
+                                Ok(()) => {
+                                    *ctxt = new_ctxt;
+                                    debug!("reloaded!");
+                                }
+                                Err(error) => {
+                                    warn!(%error, "The template customization callback returned an error");
+                                    warn!("The existing templates will remain active.");
+                                }
                             }
-                        }
-                    } else {
-                        warn_!("An error occurred while reloading templates.");
-                        warn_!("The existing templates will remain active.");
-                    };
+                        } else {
+                            warn!("An error occurred while reloading templates.");
+                            warn!("The existing templates will remain active.");
+                        };
+                    });
                 }
             });
         }
@@ -167,23 +171,22 @@ impl Fairing for TemplateFairing {
         let root = Source::from(&*path);
         match Context::initialize(path) {
             Some(mut ctxt) => {
-                use rocket::{logger::PaintExt, yansi::Paint};
+                use rocket::{trace::PaintExt, yansi::Paint};
                 use crate::templates::Engines;
 
-                info!("{}{}", Paint::emoji("📐 "), Paint::magenta("Templating:"));
-
-                match (self.callback)(&mut ctxt.engines) {
-                    Ok(()) => {
-                        info_!("directory: {}", Paint::white(root));
-                        info_!("engines: {:?}", Paint::white(Engines::ENABLED_EXTENSIONS));
-                        Ok(rocket.manage(ContextManager::new(ctxt)))
-                    }
-                    Err(e) => {
-                        error_!("The template customization callback returned an error:");
-                        error_!("{}", e);
-                        Err(rocket)
+                info_span!("templating", "{}{}", Paint::emoji("📐 "), Paint::magenta("Templating:")).in_scope(|| {
+                    match (self.callback)(&mut ctxt.engines) {
+                        Ok(()) => {
+                            info!(directory = %Paint::white(&root));
+                            info!(engines = ?Paint::white(Engines::ENABLED_EXTENSIONS));
+                            Ok(rocket.manage(ContextManager::new(ctxt)))
+                        }
+                        Err(error) => {
+                            error!(%error, "The template customization callback returned an error");
+                            Err(rocket)
+                        }
                     }
-                }
+                })
             }
             None => Err(rocket),
         }

contrib/lib/src/templates/handlebars_templates.rs

@@ -12,9 +12,10 @@ impl Engine for Handlebars<'static> {
         for &(name, info) in templates {
             let path = &info.path;
             if let Err(e) = hb.register_template_file(name, path) {
-                error!("Error in Handlebars template '{}'.", name);
-                info_!("{}", e);
-                info_!("Template path: '{}'.", path.to_string_lossy());
+                error_span!("template_error", template = %name, "Error in Handlebars template",).in_scope(|| {
+                    info!(template.error = %e);
+                    info!(template.path = %path.to_string_lossy());
+                });
                 return None;
             }
         }
@@ -24,14 +25,14 @@ impl Engine for Handlebars<'static> {
 
     fn render<C: Serialize>(&self, name: &str, context: C) -> Option<String> {
         if self.get_template(name).is_none() {
-            error_!("Handlebars template '{}' does not exist.", name);
+            error!(template = %name, "Handlebars template does not exist.");
             return None;
         }
 
         match Handlebars::render(self, name, &context) {
             Ok(string) => Some(string),
-            Err(e) => {
-                error_!("Error rendering Handlebars template '{}': {}", name, e);
+            Err(error) => {
+                error!(template = %name, %error, "Error rendering Handlebars template");
                 None
             }
         }

contrib/lib/src/templates/metadata.rs

@@ -93,9 +93,10 @@ impl<'a, 'r> FromRequest<'a, 'r> for Metadata<'a> {
             .succeeded()
             .and_then(|cm| Some(request::Outcome::Success(Metadata(cm.inner()))))
             .unwrap_or_else(|| {
-                error_!("Uninitialized template context: missing fairing.");
-                info_!("To use templates, you must attach `Template::fairing()`.");
-                info_!("See the `Template` documentation for more information.");
+                error_span!("missing_fairing", "Uninitialized template context: missing fairing.").in_scope(|| {
+                    info!("To use templates, you must attach `Template::fairing()`.");
+                    info!("See the `Template` documentation for more information.");
+                });
                 request::Outcome::Failure((Status::InternalServerError, ()))
             })
     }