Use 'tracing' library instead of 'log'.

'tracing' is now used for all messages and for Rocket's default logger.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: Jeb Rosen <jeb@jebrosen.com>

contrib/lib/Cargo.toml

@@ -45,7 +45,7 @@ diesel_mysql_pool = ["databases", "diesel/mysql", "diesel/r2d2"]
 tokio = { version = "1.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, features = ["derive"] }

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/connection.rs

@@ -4,6 +4,7 @@ use std::sync::Arc;
 use rocket::{Rocket, Phase};
 use rocket::fairing::{AdHoc, Fairing};
 use rocket::request::{Request, Outcome, FromRequest};
+use rocket::trace::error;
 use rocket::outcome::IntoOutcome;
 use rocket::http::Status;
 
@@ -62,8 +63,8 @@ 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);
+        error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);
+        error!($efmt, $error);
         return Err($rocket);
     });
 }
@@ -96,7 +97,7 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
         let permit = match timeout(duration, self.semaphore.clone().acquire_owned()).await {
             Ok(p) => p.expect("internal invariant broken: semaphore should not be closed"),
             Err(_) => {
-                error_!("database connection retrieval timed out");
+                error!("database connection retrieval timed out");
                 return Err(());
             }
         };
@@ -111,7 +112,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(())
             }
         }
@@ -123,12 +124,12 @@ impl<K: 'static, C: Poolable> ConnectionPool<K, C> {
             Some(pool) => match pool.get().await.ok() {
                 Some(conn) => Some(conn),
                 None => {
-                    error_!("no connections available for `{}`", std::any::type_name::<K>());
+                    error!("no connections available for `{}`", std::any::type_name::<K>());
                     None
                 }
             },
             None => {
-                error_!("missing database fairing for `{}`", std::any::type_name::<K>());
+                error!("missing database fairing for `{}`", std::any::type_name::<K>());
                 None
             }
         }
@@ -190,7 +191,7 @@ impl<'r, K: 'static, C: Poolable> FromRequest<'r> for Connection<K, C> {
         match request.rocket().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,8 @@ 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!(header = %name, "Space Helmet: response contains already contains this header");
+                warn!("Refusing to overwrite existing header.");
                 continue
             }
 
@@ -202,9 +202,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

@@ -197,7 +197,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

@@ -185,7 +185,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

@@ -317,8 +317,7 @@ 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()));
+            error!(path = %Paint::white(path.display()), "Bad `StaticFiles` path: invalid directory");
             panic!("refusing to continue due to invalid static files path");
         }
 

contrib/lib/src/templates/context.rs

@@ -37,10 +37,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, "Additional");
+                        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((watcher, Mutex::new(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
                 }
             };
@@ -94,20 +95,23 @@ mod context {
                 .map(|(_, rx)| rx.lock().expect("fsevents lock").try_iter().count() > 0);
 
             if let Some(true) = templates_changes {
-                info_!("Change detected: reloading templates.");
+                let span = info_span!("Change detected: reloading templates.");
+                let _e = span.enter();
                 let root = self.context().root.clone();
                 if let Some(mut new_ctxt) = Context::initialize(&root) {
                     match callback(&mut new_ctxt.engines) {
-                        Ok(()) => *self.context_mut() = new_ctxt,
-                        Err(e) => {
-                            warn_!("The template customization callback returned an error:");
-                            warn_!("{}", e);
-                            warn_!("The existing templates will remain active.");
+                        Ok(()) => {
+                            *self.context_mut() = 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.");
+                    warn!("An error occurred while reloading templates.");
+                    warn!("The existing templates will remain active.");
                 };
             }
         }
@@ -159,29 +163,29 @@ impl Fairing for TemplateFairing {
             Some(mut ctxt) => {
                 match (self.callback)(&mut ctxt.engines) {
                     Ok(()) => Ok(rocket.manage(ContextManager::new(ctxt))),
-                    Err(e) => {
-                        error_!("The template customization callback returned an error:");
-                        error_!("{}", e);
+                    Err(error) => {
+                        error!(%error, "The template customization callback returned an error");
                         Err(rocket)
                     }
                 }
             }
             None => {
-                error_!("Launch will be aborted due to failed template initialization.");
+                error!("Launch will be aborted due to failed template initialization.");
                 Err(rocket)
             }
         }
     }
 
     async fn on_liftoff(&self, rocket: &Rocket<Orbit>) {
-        use rocket::{figment::Source, logger::PaintExt, yansi::Paint};
+        use rocket::{figment::Source, trace::PaintExt, yansi::Paint};
 
         let cm = rocket.state::<ContextManager>()
             .expect("Template ContextManager registered in on_ignite");
 
-        info!("{}{}:", Paint::emoji("📐 "), Paint::magenta("Templating"));
-        info_!("directory: {}", Paint::white(Source::from(&*cm.context().root)));
-        info_!("engines: {:?}", Paint::white(Engines::ENABLED_EXTENSIONS));
+        let span = info_span!("templating", "{}{}:", Paint::emoji("📐 "), Paint::magenta("Templating"));
+        let _e = span.enter();
+        info!(directory = %Paint::white(Source::from(&*cm.context().root)));
+        info!(engines = ?Paint::white(Engines::ENABLED_EXTENSIONS));
     }
 
     #[cfg(debug_assertions)]

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<'r> FromRequest<'r> for Metadata<'r> {
             .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, ()))
             })
     }

contrib/lib/src/templates/mod.rs

@@ -377,9 +377,10 @@ impl Template {
         where S: Into<Cow<'static, str>>, C: Serialize
     {
         let ctxt = rocket.state::<ContextManager>().map(ContextManager::context).or_else(|| {
-            warn!("Uninitialized template context: missing fairing.");
-            info!("To use templates, you must attach `Template::fairing()`.");
-            info!("See the `Template` documentation for more information.");
+            warn_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.");
+            });
             None
         })?;
 
@@ -394,19 +395,20 @@ impl Template {
         let name = &*self.name;
         let info = ctxt.templates.get(name).ok_or_else(|| {
             let ts: Vec<_> = ctxt.templates.keys().map(|s| s.as_str()).collect();
-            error_!("Template '{}' does not exist.", name);
-            info_!("Known templates: {}", ts.join(", "));
-            info_!("Searched in {:?}.", ctxt.root);
+            error_span!("Template does not exist.", template = %name).in_scope(|| {
+                info!("Known templates: {}", ts.join(","));
+                info!("Searched in {:?}.", ctxt.root);
+            });
             Status::InternalServerError
         })?;
 
         let value = self.value.ok_or_else(|| {
-            error_!("The provided template context failed to serialize.");
+            error!("The provided template context failed to serialize.");
             Status::InternalServerError
         })?;
 
         let string = ctxt.engines.render(name, &info, value).ok_or_else(|| {
-            error_!("Template '{}' failed to render.", name);
+            error!(template = %name, "Template failed to render.");
             Status::InternalServerError
         })?;
 
@@ -421,9 +423,10 @@ impl<'r> Responder<'r, 'static> for Template {
     fn respond_to(self, req: &'r Request<'_>) -> response::Result<'static> {
         let (render, content_type) = {
             let ctxt = req.rocket().state::<ContextManager>().ok_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.");
+                });
                 Status::InternalServerError
             })?.context();