From b12b7f27d716949880ae3af7f5ad3869e8f436cc Mon Sep 17 00:00:00 2001 From: Sergio Benitez Date: Wed, 15 May 2024 04:07:47 -0700 Subject: [PATCH] Remove old 'log' macros. Color via subscriber. This commit: - Removes painting outside trace subscriber in core. - Removes all non-subscriber uses of yansi. - Removes all uses of old log macros. - Fix trace exports. --- contrib/db_pools/lib/src/database.rs | 16 ++-- contrib/dyn_templates/src/context.rs | 37 +++++----- .../dyn_templates/src/engine/handlebars.rs | 20 ++--- contrib/dyn_templates/src/engine/minijinja.rs | 23 +++--- contrib/dyn_templates/src/engine/tera.rs | 37 +++++----- contrib/dyn_templates/src/fairing.rs | 4 +- contrib/dyn_templates/src/metadata.rs | 19 ++--- contrib/dyn_templates/src/template.rs | 53 +++++++------ contrib/sync_db_pools/lib/src/connection.rs | 64 ++++++++-------- core/codegen/src/attribute/route/mod.rs | 27 ++++--- core/http/src/uri/error.rs | 12 +++ core/lib/src/catcher/catcher.rs | 17 ----- core/lib/src/config/config.rs | 2 +- core/lib/src/data/peekable.rs | 2 +- core/lib/src/error.rs | 74 ++++++++++--------- core/lib/src/fairing/ad_hoc.rs | 8 +- core/lib/src/form/parser.rs | 4 +- core/lib/src/lib.rs | 1 - core/lib/src/lifecycle.rs | 4 +- core/lib/src/request/from_param.rs | 5 +- core/lib/src/request/request.rs | 9 +-- core/lib/src/response/body.rs | 4 +- core/lib/src/response/debug.rs | 8 +- core/lib/src/response/responder.rs | 5 +- core/lib/src/rocket.rs | 21 +++--- core/lib/src/route/route.rs | 23 ------ core/lib/src/route/uri.rs | 16 ---- core/lib/src/router/collider.rs | 4 +- core/lib/src/router/router.rs | 4 +- core/lib/src/serde/json.rs | 2 +- core/lib/src/serde/msgpack.rs | 2 +- core/lib/src/server.rs | 2 +- core/lib/src/shield/shield.rs | 41 ++++------ core/lib/src/state.rs | 5 +- core/lib/src/tls/resolver.rs | 7 +- core/lib/src/trace/macros.rs | 51 +++++++------ core/lib/src/trace/mod.rs | 19 +++-- core/lib/src/trace/subscriber/common.rs | 16 ++-- core/lib/src/trace/subscriber/mod.rs | 2 +- core/lib/src/trace/subscriber/pretty.rs | 1 + core/lib/src/trace/subscriber/request_id.rs | 4 +- core/lib/src/trace/traceable.rs | 11 ++- examples/hello/src/main.rs | 2 - examples/state/src/request_local.rs | 10 --- examples/tls/src/redirector.rs | 28 ++++--- examples/todo/src/main.rs | 8 +- 46 files changed, 350 insertions(+), 384 deletions(-) diff --git a/contrib/db_pools/lib/src/database.rs b/contrib/db_pools/lib/src/database.rs index 6f9ae407..4467eaed 100644 --- a/contrib/db_pools/lib/src/database.rs +++ b/contrib/db_pools/lib/src/database.rs @@ -1,13 +1,11 @@ use std::marker::PhantomData; use std::ops::{Deref, DerefMut}; -use rocket::{error, info_, Build, Ignite, Phase, Rocket, Sentinel, Orbit}; +use rocket::{error, Build, Ignite, Phase, Rocket, Sentinel, Orbit}; use rocket::fairing::{self, Fairing, Info, Kind}; use rocket::request::{FromRequest, Outcome, Request}; -use rocket::http::Status; - -use rocket::yansi::Paint; use rocket::figment::providers::Serialized; +use rocket::http::Status; use crate::Pool; @@ -122,10 +120,10 @@ pub trait Database: From + DerefMut + Send + Sy return Some(db); } - let dbtype = std::any::type_name::().bold().primary(); - error!("Attempted to fetch unattached database `{}`.", dbtype); - info_!("`{}{}` fairing must be attached prior to using this database.", - dbtype.linger(), "::init()".resetting()); + let conn = std::any::type_name::(); + error!("`{conn}::init()` is not attached\n\ + the fairing must be attached to use `{conn}` in routes."); + None } } @@ -267,7 +265,7 @@ impl Fairing for Initializer { match ::init(&figment).await { Ok(pool) => Ok(rocket.manage(D::from(pool))), Err(e) => { - error!("failed to initialize database: {}", e); + error!("database initialization failed: {e}"); Err(rocket) } } diff --git a/contrib/dyn_templates/src/context.rs b/contrib/dyn_templates/src/context.rs index 33e260a0..1bab926d 100644 --- a/contrib/dyn_templates/src/context.rs +++ b/contrib/dyn_templates/src/context.rs @@ -49,16 +49,17 @@ impl Context { Ok(_) | Err(_) => continue, }; - let (name, data_type_str) = split_path(&root, entry.path()); - if let Some(info) = templates.get(&*name) { - warn_!("Template name '{}' does not have a unique source.", name); - match info.path { - Some(ref path) => info_!("Existing path: {:?}", path), - None => info_!("Existing Content-Type: {}", info.data_type), - } + let (template, data_type_str) = split_path(&root, entry.path()); + if let Some(info) = templates.get(&*template) { + warn!( + %template, + first_path = %entry.path().display(), + second_path = info.path.as_ref().map(|p| display(p.display())), + data_type = %info.data_type, + "Template name '{template}' can refer to multiple templates.\n\ + First path will be used. Second path is ignored." + ); - info_!("Additional path: {:?}", entry.path()); - warn_!("Keeping existing template '{}'.", name); continue; } @@ -66,7 +67,7 @@ impl Context { .and_then(|ext| ContentType::from_extension(ext)) .unwrap_or(ContentType::Text); - templates.insert(name, TemplateInfo { + templates.insert(template, TemplateInfo { path: Some(entry.into_path()), engine_ext: ext, data_type, @@ -75,9 +76,8 @@ impl Context { } let mut engines = Engines::init(&templates)?; - if let Err(e) = callback(&mut engines) { - error_!("Template customization callback failed."); - error_!("{}", e); + if let Err(reason) = callback(&mut engines) { + error!(%reason, "template customization callback failed"); return None; } @@ -151,9 +151,8 @@ mod manager { 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."); + warn!("live template reloading initialization failed: {e}\n\ + live template reloading is unavailable"); None } }; @@ -182,13 +181,13 @@ mod manager { .map(|(_, rx)| rx.lock().expect("fsevents lock").try_iter().count() > 0); if let Some(true) = templates_changes { - info_!("Change detected: reloading templates."); + debug!("template change detected: reloading templates"); let root = self.context().root.clone(); if let Some(new_ctxt) = Context::initialize(&root, callback) { *self.context_mut() = new_ctxt; } else { - warn_!("An error occurred while reloading templates."); - warn_!("Existing templates will remain active."); + warn!("error while reloading template\n\ + existing templates will remain active.") }; } } diff --git a/contrib/dyn_templates/src/engine/handlebars.rs b/contrib/dyn_templates/src/engine/handlebars.rs index 57f0c6ee..f567ba39 100644 --- a/contrib/dyn_templates/src/engine/handlebars.rs +++ b/contrib/dyn_templates/src/engine/handlebars.rs @@ -11,11 +11,11 @@ impl Engine for Handlebars<'static> { fn init<'a>(templates: impl Iterator) -> Option { let mut hb = Handlebars::new(); let mut ok = true; - for (name, path) in templates { - if let Err(e) = hb.register_template_file(name, path) { - error!("Handlebars template '{}' failed to register.", name); - error_!("{}", e); - info_!("Template path: '{}'.", path.to_string_lossy()); + for (template, path) in templates { + if let Err(e) = hb.register_template_file(template, path) { + error!(template, path = %path.display(), + "failed to register Handlebars template: {e}"); + ok = false; } } @@ -23,14 +23,14 @@ impl Engine for Handlebars<'static> { ok.then_some(hb) } - fn render(&self, name: &str, context: C) -> Option { - if self.get_template(name).is_none() { - error_!("Handlebars template '{}' does not exist.", name); + fn render(&self, template: &str, context: C) -> Option { + if self.get_template(template).is_none() { + error!(template, "requested Handlebars template does not exist."); return None; } - Handlebars::render(self, name, &context) - .map_err(|e| error_!("Handlebars: {}", e)) + Handlebars::render(self, template, &context) + .map_err(|e| error!("Handlebars render error: {}", e)) .ok() } } diff --git a/contrib/dyn_templates/src/engine/minijinja.rs b/contrib/dyn_templates/src/engine/minijinja.rs index 8f2296e9..461b3209 100644 --- a/contrib/dyn_templates/src/engine/minijinja.rs +++ b/contrib/dyn_templates/src/engine/minijinja.rs @@ -43,23 +43,22 @@ impl Engine for Environment<'static> { } fn render(&self, name: &str, context: C) -> Option { - let template = match self.get_template(name) { - Ok(template) => template, - Err(e) => { - error_!("Minijinja template '{name}' error: {e}"); - return None; - } + let Ok(template) = self.get_template(name) else { + error!("Minijinja template '{name}' was not found."); + return None; }; match template.render(context) { Ok(result) => Some(result), Err(e) => { - error_!("Error rendering Minijinja template '{name}': {e}"); - let mut error = &e as &dyn std::error::Error; - while let Some(source) = error.source() { - error_!("caused by: {source}"); - error = source; - } + error_span!("Error rendering Minijinja template '{name}': {e}" => { + let mut error = &e as &dyn std::error::Error; + while let Some(source) = error.source() { + error_!("caused by: {source}"); + error = source; + } + }); + None } } diff --git a/contrib/dyn_templates/src/engine/tera.rs b/contrib/dyn_templates/src/engine/tera.rs index 9cba0e8a..af548b7b 100644 --- a/contrib/dyn_templates/src/engine/tera.rs +++ b/contrib/dyn_templates/src/engine/tera.rs @@ -21,13 +21,13 @@ impl Engine for Tera { // Finally try to tell Tera about all of the templates. if let Err(e) = tera.add_template_files(files) { - error!("Failed to initialize Tera templating."); - - let mut error = Some(&e as &dyn Error); - while let Some(err) = error { - info_!("{}", err); - error = err.source(); - } + error_span!("Tera templating initialization failed" => { + let mut error = Some(&e as &dyn Error); + while let Some(err) = error { + error!("{err}"); + error = err.source(); + } + }); None } else { @@ -35,25 +35,26 @@ impl Engine for Tera { } } - fn render(&self, name: &str, context: C) -> Option { - if self.get_template(name).is_err() { - error_!("Tera template '{}' does not exist.", name); + fn render(&self, template: &str, context: C) -> Option { + if self.get_template(template).is_err() { + error!(template, "requested template does not exist"); return None; }; let tera_ctx = Context::from_serialize(context) - .map_err(|e| error_!("Tera context error: {}.", e)) + .map_err(|e| error!("Tera context error: {}.", e)) .ok()?; - match Tera::render(self, name, &tera_ctx) { + match Tera::render(self, template, &tera_ctx) { Ok(string) => Some(string), Err(e) => { - error_!("Error rendering Tera template '{name}': {e}"); - let mut error = Some(&e as &dyn Error); - while let Some(err) = error { - error_!("{}", err); - error = err.source(); - } + error_span!("failed to render Tera template {name}" [template] => { + let mut error = Some(&e as &dyn Error); + while let Some(err) = error { + error!("{err}"); + error = err.source(); + } + }); None } diff --git a/contrib/dyn_templates/src/fairing.rs b/contrib/dyn_templates/src/fairing.rs index 949fecf3..4079de8a 100644 --- a/contrib/dyn_templates/src/fairing.rs +++ b/contrib/dyn_templates/src/fairing.rs @@ -48,7 +48,7 @@ impl Fairing for TemplateFairing { if let Some(ctxt) = Context::initialize(&path, &self.callback) { Ok(rocket.manage(ContextManager::new(ctxt))) } else { - error_!("Template initialization failed. Aborting launch."); + error!("Template initialization failed. Aborting launch."); Err(rocket) } } @@ -57,7 +57,7 @@ impl Fairing for TemplateFairing { let cm = rocket.state::() .expect("Template ContextManager registered in on_ignite"); - info_span!("templating" [icon = "📐"] => { + info_span!("templating" => { info!(directory = %Source::from(&*cm.context().root)); info!(engines = ?Engines::ENABLED_EXTENSIONS); }); diff --git a/contrib/dyn_templates/src/metadata.rs b/contrib/dyn_templates/src/metadata.rs index da774de1..8c19b1f5 100644 --- a/contrib/dyn_templates/src/metadata.rs +++ b/contrib/dyn_templates/src/metadata.rs @@ -5,7 +5,6 @@ use rocket::{Request, Rocket, Ignite, Sentinel}; use rocket::http::{Status, ContentType}; use rocket::request::{self, FromRequest}; use rocket::serde::Serialize; -use rocket::yansi::Paint; use crate::{Template, context::ContextManager}; @@ -136,11 +135,11 @@ impl fmt::Debug for Metadata<'_> { impl Sentinel for Metadata<'_> { fn abort(rocket: &Rocket) -> bool { if rocket.state::().is_none() { - let md = "Metadata".primary().bold(); - let fairing = "Template::fairing()".primary().bold(); - error!("requested `{}` guard without attaching `{}`.", md, fairing); - info_!("To use or query templates, you must attach `{}`.", fairing); - info_!("See the `Template` documentation for more information."); + error!( + "uninitialized template context: missing `Template::fairing()`.\n\ + To use templates, you must attach `Template::fairing()`." + ); + return true; } @@ -159,9 +158,11 @@ impl<'r> FromRequest<'r> for Metadata<'r> { request.rocket().state::() .map(|cm| request::Outcome::Success(Metadata(cm))) .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!( + "uninitialized template context: missing `Template::fairing()`.\n\ + To use templates, you must attach `Template::fairing()`." + ); + request::Outcome::Error((Status::InternalServerError, ())) }) } diff --git a/contrib/dyn_templates/src/template.rs b/contrib/dyn_templates/src/template.rs index 2cf88a8c..9b4f6a31 100644 --- a/contrib/dyn_templates/src/template.rs +++ b/contrib/dyn_templates/src/template.rs @@ -7,8 +7,8 @@ use rocket::fairing::Fairing; use rocket::response::{self, Responder}; use rocket::http::{ContentType, Status}; use rocket::figment::{value::Value, error::Error}; +use rocket::trace::Traceable; use rocket::serde::Serialize; -use rocket::yansi::Paint; use crate::Engines; use crate::fairing::TemplateFairing; @@ -218,12 +218,15 @@ impl Template { pub fn show(rocket: &Rocket, name: S, context: C) -> Option where S: Into>, C: Serialize { - let ctxt = rocket.state::().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."); - None - })?; + let ctxt = rocket.state::() + .map(ContextManager::context) + .or_else(|| { + error!("Uninitialized template context: missing fairing.\n\ + To use templates, you must attach `Template::fairing()`.\n\ + See the `Template` documentation for more information."); + + None + })?; Template::render(name, context).finalize(&ctxt).ok().map(|v| v.1) } @@ -233,22 +236,24 @@ impl Template { /// `Template::show()`. #[inline(always)] pub(crate) fn finalize(self, ctxt: &Context) -> Result<(ContentType, String), Status> { - let name = &*self.name; - let info = ctxt.templates.get(name).ok_or_else(|| { + let template = &*self.name; + let info = ctxt.templates.get(template).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!( + %template, search_path = %ctxt.root.display(), known_templates = ?ts, + "requested template not found" + ); + Status::InternalServerError })?; let value = self.value.map_err(|e| { - error_!("Template context failed to serialize: {}.", e); + error_span!("template context failed to serialize" => e.trace_error()); Status::InternalServerError })?; - let string = ctxt.engines.render(name, info, value).ok_or_else(|| { - error_!("Template '{}' failed to render.", name); + let string = ctxt.engines.render(template, info, value).ok_or_else(|| { + error!(template, "template failed to render"); Status::InternalServerError })?; @@ -264,9 +269,11 @@ impl<'r> Responder<'r, 'static> for Template { let ctxt = req.rocket() .state::() .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!( + "uninitialized template context: missing `Template::fairing()`.\n\ + To use templates, you must attach `Template::fairing()`." + ); + Status::InternalServerError })?; @@ -277,11 +284,11 @@ impl<'r> Responder<'r, 'static> for Template { impl Sentinel for Template { fn abort(rocket: &Rocket) -> bool { if rocket.state::().is_none() { - let template = "Template".primary().bold(); - let fairing = "Template::fairing()".primary().bold(); - error!("returning `{}` responder without attaching `{}`.", template, fairing); - info_!("To use or query templates, you must attach `{}`.", fairing); - info_!("See the `Template` documentation for more information."); + error!( + "Missing `Template::fairing()`.\n\ + To use templates, you must attach `Template::fairing()`." + ); + return true; } diff --git a/contrib/sync_db_pools/lib/src/connection.rs b/contrib/sync_db_pools/lib/src/connection.rs index 0d4ac19f..d152f1a5 100644 --- a/contrib/sync_db_pools/lib/src/connection.rs +++ b/contrib/sync_db_pools/lib/src/connection.rs @@ -1,14 +1,15 @@ -use std::marker::PhantomData; use std::sync::Arc; +use std::marker::PhantomData; use rocket::{Phase, Rocket, Ignite, Sentinel}; use rocket::fairing::{AdHoc, Fairing}; use rocket::request::{Request, Outcome, FromRequest}; use rocket::outcome::IntoOutcome; use rocket::http::Status; +use rocket::trace::Traceable; -use rocket::tokio::sync::{OwnedSemaphorePermit, Semaphore, Mutex}; use rocket::tokio::time::timeout; +use rocket::tokio::sync::{OwnedSemaphorePermit, Semaphore, Mutex}; use crate::{Config, Poolable, Error}; @@ -60,45 +61,50 @@ async fn run_blocking(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); - return Err($rocket); - }); -} - impl ConnectionPool { - pub fn fairing(fairing_name: &'static str, db: &'static str) -> impl Fairing { + pub fn fairing(fairing_name: &'static str, database: &'static str) -> impl Fairing { AdHoc::try_on_ignite(fairing_name, move |rocket| async move { run_blocking(move || { - let config = match Config::from(db, &rocket) { + let config = match Config::from(database, &rocket) { Ok(config) => config, - Err(e) => dberr!("config", db, "{}", e, rocket), + Err(e) => { + error_span!("database configuration error" [database] => e.trace_error()); + return Err(rocket); + } }; let pool_size = config.pool_size; - match C::pool(db, &rocket) { + match C::pool(database, &rocket) { Ok(pool) => Ok(rocket.manage(ConnectionPool:: { config, pool: Some(pool), 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)) => { + error_span!("database configuration error" [database] => e.trace_error()); + Err(rocket) + } + Err(Error::Pool(reason)) => { + error!(database, %reason, "database pool initialization failed"); + Err(rocket) + } + Err(Error::Custom(reason)) => { + error!(database, ?reason, "database pool failure"); + Err(rocket) + } } }).await }) } pub async fn get(&self) -> Option> { + let type_name = std::any::type_name::(); let duration = std::time::Duration::from_secs(self.config.timeout as u64); 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!(type_name, "database connection retrieval timed out"); return None; } }; @@ -113,7 +119,7 @@ impl ConnectionPool { _marker: PhantomData, }), Err(e) => { - error_!("failed to get a database connection: {}", e); + error!(type_name, "failed to get a database connection: {}", e); None } } @@ -125,12 +131,12 @@ impl ConnectionPool { Some(pool) => match pool.get().await { Some(conn) => Some(conn), None => { - error_!("no connections available for `{}`", std::any::type_name::()); + error!("no connections available for `{}`", std::any::type_name::()); None } }, None => { - error_!("missing database fairing for `{}`", std::any::type_name::()); + error!("missing database fairing for `{}`", std::any::type_name::()); None } } @@ -165,6 +171,7 @@ impl Connection { let conn = connection.as_mut() .expect("internal invariant broken: self.connection is Some"); + f(conn) }).await } @@ -212,7 +219,9 @@ impl<'r, K: 'static, C: Poolable> FromRequest<'r> for Connection { match request.rocket().state::>() { Some(c) => c.get().await.or_error((Status::ServiceUnavailable, ())), None => { - error_!("Missing database fairing for `{}`", std::any::type_name::()); + let conn = std::any::type_name::(); + error!("`{conn}::fairing()` is not attached\n\ + the fairing must be attached to use `{conn} in routes."); Outcome::Error((Status::InternalServerError, ())) } } @@ -221,15 +230,10 @@ impl<'r, K: 'static, C: Poolable> FromRequest<'r> for Connection { impl Sentinel for Connection { fn abort(rocket: &Rocket) -> bool { - use rocket::yansi::Paint; - if rocket.state::>().is_none() { - let conn = std::any::type_name::().primary().bold(); - error!("requesting `{}` DB connection without attaching `{}{}`.", - conn, conn.linger(), "::fairing()".resetting()); - - info_!("Attach `{}{}` to use database connection pooling.", - conn.linger(), "::fairing()".resetting()); + let conn = std::any::type_name::(); + error!("`{conn}::fairing()` is not attached\n\ + the fairing must be attached to use `{conn} in routes."); return true; } diff --git a/core/codegen/src/attribute/route/mod.rs b/core/codegen/src/attribute/route/mod.rs index 6b9faab5..7850e73e 100644 --- a/core/codegen/src/attribute/route/mod.rs +++ b/core/codegen/src/attribute/route/mod.rs @@ -105,8 +105,10 @@ fn query_decls(route: &Route) -> Option { )* if !__e.is_empty() { - ::rocket::warn_!("Query string failed to match route declaration."); - for _err in __e { ::rocket::warn_!("{}", _err); } + ::rocket::info_span!("query string failed to match route declaration" => { + for _err in __e { ::rocket::info!("{_err}"); } + }); + return #Outcome::Forward((#__data, #Status::UnprocessableEntity)); } @@ -125,11 +127,11 @@ fn request_guard_decl(guard: &Guard) -> TokenStream { let #ident: #ty = match <#ty as #FromRequest>::from_request(#__req).await { #Outcome::Success(__v) => __v, #Outcome::Forward(__e) => { - ::rocket::warn_!("Request guard `{}` is forwarding.", stringify!(#ty)); + ::rocket::info!(type_name = stringify!(#ty), "guard forwarding"); return #Outcome::Forward((#__data, __e)); }, #Outcome::Error((__c, __e)) => { - ::rocket::warn_!("Request guard `{}` failed: {:?}.", stringify!(#ty), __e); + ::rocket::info!(type_name = stringify!(#ty), "guard failed: {__e:?}"); return #Outcome::Error(__c); } }; @@ -145,8 +147,9 @@ fn param_guard_decl(guard: &Guard) -> TokenStream { // Returned when a dynamic parameter fails to parse. let parse_error = quote!({ - ::rocket::warn_!("Parameter guard `{}: {}` is forwarding: {:?}.", - #name, stringify!(#ty), __error); + ::rocket::info!(name: "forward", + reason = %__error, parameter = #name, "type" = stringify!(#ty), + "parameter forwarding"); #Outcome::Forward((#__data, #Status::UnprocessableEntity)) }); @@ -161,9 +164,11 @@ fn param_guard_decl(guard: &Guard) -> TokenStream { #_Err(__error) => return #parse_error, }, #_None => { - ::rocket::error_!("Internal invariant broken: dyn param {} not found.", #i); - ::rocket::error_!("Please report this to the Rocket issue tracker."); - ::rocket::error_!("https://github.com/rwf2/Rocket/issues"); + ::rocket::error!( + "Internal invariant broken: dyn param {} not found.\n\ + Please report this to the Rocket issue tracker.\n\ + https://github.com/rwf2/Rocket/issues", #i); + return #Outcome::Forward((#__data, #Status::InternalServerError)); } } @@ -188,11 +193,11 @@ fn data_guard_decl(guard: &Guard) -> TokenStream { let #ident: #ty = match <#ty as #FromData>::from_data(#__req, #__data).await { #Outcome::Success(__d) => __d, #Outcome::Forward((__d, __e)) => { - ::rocket::warn_!("Data guard `{}` is forwarding.", stringify!(#ty)); + ::rocket::info!(type_name = stringify!(#ty), "data guard forwarding"); return #Outcome::Forward((__d, __e)); } #Outcome::Error((__c, __e)) => { - ::rocket::warn_!("Data guard `{}` failed: {:?}.", stringify!(#ty), __e); + ::rocket::info!(type_name = stringify!(#ty), "data guard failed: {__e:?}"); return #Outcome::Error(__c); } }; diff --git a/core/http/src/uri/error.rs b/core/http/src/uri/error.rs index 3b976c61..06705d27 100644 --- a/core/http/src/uri/error.rs +++ b/core/http/src/uri/error.rs @@ -28,3 +28,15 @@ pub enum PathError { /// The segment ended with the wrapped invalid character. BadEnd(char), } + +impl fmt::Display for PathError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + PathError::BadStart(c) => write!(f, "invalid initial character: {c:?}"), + PathError::BadChar(c) => write!(f, "invalid character: {c:?}"), + PathError::BadEnd(c) => write!(f, "invalid terminal character: {c:?}"), + } + } +} + +impl std::error::Error for PathError { } diff --git a/core/lib/src/catcher/catcher.rs b/core/lib/src/catcher/catcher.rs index de996205..2a82b05c 100644 --- a/core/lib/src/catcher/catcher.rs +++ b/core/lib/src/catcher/catcher.rs @@ -8,8 +8,6 @@ use crate::request::Request; use crate::http::{Status, ContentType, uri}; use crate::catcher::{Handler, BoxFuture}; -use yansi::Paint; - /// An error catching route. /// /// Catchers are routes that run when errors are produced by the application. @@ -342,21 +340,6 @@ impl From for Catcher { } } -impl fmt::Display for Catcher { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - if let Some(ref n) = self.name { - write!(f, "{}{}{} ", "(".cyan(), n.primary(), ")".cyan())?; - } - - write!(f, "{} ", self.base.path().green())?; - - match self.code { - Some(code) => write!(f, "{}", code.blue()), - None => write!(f, "{}", "default".blue()), - } - } -} - impl fmt::Debug for Catcher { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.debug_struct("Catcher") diff --git a/core/lib/src/config/config.rs b/core/lib/src/config/config.rs index b5f19842..134e5867 100644 --- a/core/lib/src/config/config.rs +++ b/core/lib/src/config/config.rs @@ -10,7 +10,7 @@ use crate::config::{ShutdownConfig, Ident, CliColors}; use crate::request::{self, Request, FromRequest}; use crate::http::uncased::Uncased; use crate::data::Limits; -use crate::trace::traceable::Traceable; +use crate::trace::Traceable; /// Rocket server configuration. /// diff --git a/core/lib/src/data/peekable.rs b/core/lib/src/data/peekable.rs index 62896735..920aaa94 100644 --- a/core/lib/src/data/peekable.rs +++ b/core/lib/src/data/peekable.rs @@ -37,7 +37,7 @@ impl Peekable { }, Ok(_) => { /* continue */ }, Err(e) => { - error_!("Failed to read into peek buffer: {:?}.", e); + error!("failed to read into peek buffer: {:?}.", e); break; } } diff --git a/core/lib/src/error.rs b/core/lib/src/error.rs index 78252d55..8d8934f6 100644 --- a/core/lib/src/error.rs +++ b/core/lib/src/error.rs @@ -7,7 +7,7 @@ use std::sync::Arc; use figment::Profile; use crate::listener::Endpoint; -use crate::trace::traceable::Traceable; +use crate::trace::Traceable; use crate::{Ignite, Orbit, Phase, Rocket}; /// An error that occurs during launch. @@ -170,46 +170,48 @@ impl fmt::Display for Empty { impl StdError for Empty { } +struct ServerError<'a>(&'a (dyn StdError + 'static)); + +impl fmt::Display for ServerError<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let error = &self.0; + if let Some(e) = error.downcast_ref::() { + write!(f, "request failed: {e}")?; + } else if let Some(e) = error.downcast_ref::() { + write!(f, "connection error: ")?; + + match e.kind() { + io::ErrorKind::NotConnected => write!(f, "remote disconnected")?, + io::ErrorKind::UnexpectedEof => write!(f, "remote sent early eof")?, + io::ErrorKind::ConnectionReset + | io::ErrorKind::ConnectionAborted => write!(f, "terminated by remote")?, + _ => write!(f, "{e}")?, + } + } else { + write!(f, "http server error: {error}")?; + } + + Ok(()) + } +} + /// Log an error that occurs during request processing #[track_caller] pub(crate) fn log_server_error(error: &(dyn StdError + 'static)) { - struct ServerError<'a>(&'a (dyn StdError + 'static)); - - impl fmt::Display for ServerError<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let error = &self.0; - if let Some(e) = error.downcast_ref::() { - write!(f, "request failed: {e}")?; - } else if let Some(e) = error.downcast_ref::() { - write!(f, "connection error: ")?; - - match e.kind() { - io::ErrorKind::NotConnected => write!(f, "remote disconnected")?, - io::ErrorKind::UnexpectedEof => write!(f, "remote sent early eof")?, - io::ErrorKind::ConnectionReset - | io::ErrorKind::ConnectionAborted => write!(f, "terminated by remote")?, - _ => write!(f, "{e}")?, - } - } else { - write!(f, "http server error: {error}")?; - } - - Ok(()) - } - } - let mut error: &(dyn StdError + 'static) = error; if error.downcast_ref::().is_some() { - warn!("{}", ServerError(error)); - while let Some(source) = error.source() { - error = source; - warn_!("{}", ServerError(error)); - } + warn_span!("minor server error" ["{}", ServerError(error)] => { + while let Some(source) = error.source() { + error = source; + warn!("{}", ServerError(error)); + } + }); } else { - error!("{}", ServerError(error)); - while let Some(source) = error.source() { - error = source; - error_!("{}", ServerError(error)); - } + error_span!("server error" ["{}", ServerError(error)] => { + while let Some(source) = error.source() { + error = source; + error!("{}", ServerError(error)); + } + }); } } diff --git a/core/lib/src/fairing/ad_hoc.rs b/core/lib/src/fairing/ad_hoc.rs index a167c42f..58e985f9 100644 --- a/core/lib/src/fairing/ad_hoc.rs +++ b/core/lib/src/fairing/ad_hoc.rs @@ -387,10 +387,10 @@ impl AdHoc { // This allows incremental compatibility updates. Otherwise, // rewrite the request URI to remove the `/`. if !self.routes(req.rocket()).iter().any(|r| r.matches(req)) { - let normal = req.uri().clone().into_normalized_nontrailing(); - warn!("Incoming request URI was normalized for compatibility."); - info_!("{} -> {}", req.uri(), normal); - req.set_uri(normal); + let normalized = req.uri().clone().into_normalized_nontrailing(); + warn!(original = %req.uri(), %normalized, + "incoming request URI normalized for compatibility"); + req.set_uri(normalized); } } } diff --git a/core/lib/src/form/parser.rs b/core/lib/src/form/parser.rs index 1a93d74e..be9130a4 100644 --- a/core/lib/src/form/parser.rs +++ b/core/lib/src/form/parser.rs @@ -115,7 +115,7 @@ impl<'r> Iterator for RawStrParser<'r> { } }; - trace_!("url-encoded field: {:?}", (name, value)); + trace!(%name, %value, "url-encoded field"); let name_val = match (name.url_decode_lossy(), value.url_decode_lossy()) { (Borrowed(name), Borrowed(val)) => (name, val), (Borrowed(name), Owned(v)) => (name, self.buffer.push(v)), @@ -168,7 +168,7 @@ impl<'r, 'i> MultipartParser<'r, 'i> { }; // A field with a content-type is data; one without is "value". - trace_!("multipart field: {:?}", field); + trace!(?field, "multipart field"); let content_type = field.content_type().and_then(|m| m.as_ref().parse().ok()); let field = if let Some(content_type) = content_type { let (name, file_name) = match (field.name(), field.file_name()) { diff --git a/core/lib/src/lib.rs b/core/lib/src/lib.rs index b42203dc..ef02e622 100644 --- a/core/lib/src/lib.rs +++ b/core/lib/src/lib.rs @@ -122,7 +122,6 @@ pub use figment; pub use time; pub use tracing; -#[doc(hidden)] #[macro_use] pub mod trace; #[macro_use] diff --git a/core/lib/src/lifecycle.rs b/core/lib/src/lifecycle.rs index 72eac73c..26f17ed6 100644 --- a/core/lib/src/lifecycle.rs +++ b/core/lib/src/lifecycle.rs @@ -1,7 +1,7 @@ use futures::future::{FutureExt, Future}; use crate::{route, catcher, Rocket, Orbit, Request, Response, Data}; -use crate::trace::traceable::Traceable; +use crate::trace::Traceable; use crate::util::Formatter; use crate::data::IoHandler; use crate::http::{Method, Status, Header}; @@ -275,7 +275,7 @@ impl Rocket { .map(|result| result.map_err(Some)) .unwrap_or_else(|| Err(None)) } else { - info!(name: "catcher", name = "rocket::default", code = status.code, + info!(name: "catcher", name = "rocket::default", "uri.base" = "/", code = status.code, "no registered catcher: using Rocket default"); Ok(catcher::default_handler(status, req)) } diff --git a/core/lib/src/request/from_param.rs b/core/lib/src/request/from_param.rs index 3097695c..d53a2cb3 100644 --- a/core/lib/src/request/from_param.rs +++ b/core/lib/src/request/from_param.rs @@ -204,9 +204,8 @@ impl<'a> FromParam<'a> for String { #[inline(always)] fn from_param(param: &'a str) -> Result { #[cfg(debug_assertions)] { - let loc = std::panic::Location::caller(); - warn_!("Note: Using `String` as a parameter type is inefficient. Use `&str` instead."); - info_!("`String` is used a parameter guard in {}:{}.", loc.file(), loc.line()); + let location = std::panic::Location::caller(); + warn!(%location, "`String` as a parameter is inefficient. Use `&str` instead."); } if param.is_empty() { diff --git a/core/lib/src/request/request.rs b/core/lib/src/request/request.rs index aeb99eec..93912383 100644 --- a/core/lib/src/request/request.rs +++ b/core/lib/src/request/request.rs @@ -380,7 +380,7 @@ impl<'r> Request<'r> { .get_one(ip_header) .and_then(|ip| { ip.parse() - .map_err(|_| warn_!("'{}' header is malformed: {}", ip_header, ip)) + .map_err(|_| warn!(value = ip, "'{ip_header}' header is malformed")) .ok() }) } @@ -1158,15 +1158,14 @@ impl<'r> Request<'r> { } // Set the rest of the headers. This is rather unfortunate and slow. - for (name, value) in hyper.headers.iter() { + for (header, value) in hyper.headers.iter() { // FIXME: This is rather unfortunate. Header values needn't be UTF8. let Ok(value) = std::str::from_utf8(value.as_bytes()) else { - warn!("Header '{}' contains invalid UTF-8", name); - warn_!("Rocket only supports UTF-8 header values. Dropping header."); + warn!(%header, "dropping header with invalid UTF-8"); continue; }; - request.add_header(Header::new(name.as_str(), value)); + request.add_header(Header::new(header.as_str(), value)); } match request.errors.is_empty() { diff --git a/core/lib/src/response/body.rs b/core/lib/src/response/body.rs index d37547c1..f0b2ac9b 100644 --- a/core/lib/src/response/body.rs +++ b/core/lib/src/response/body.rs @@ -352,7 +352,7 @@ impl<'r> Body<'r> { let n = match self.read_to_end(&mut vec).await { Ok(n) => n, Err(e) => { - error_!("Error reading body: {:?}", e); + error!("i/o error reading body: {:?}", e); return Err(e); } }; @@ -389,7 +389,7 @@ impl<'r> Body<'r> { /// ``` pub async fn to_string(&mut self) -> io::Result { String::from_utf8(self.to_bytes().await?).map_err(|e| { - error_!("Body is invalid UTF-8: {}", e); + error!("invalid body UTF-8: {}", e); io::Error::new(io::ErrorKind::InvalidData, e) }) } diff --git a/core/lib/src/response/debug.rs b/core/lib/src/response/debug.rs index 030b5370..a7d3e612 100644 --- a/core/lib/src/response/debug.rs +++ b/core/lib/src/response/debug.rs @@ -2,8 +2,6 @@ use crate::request::Request; use crate::response::{self, Responder}; use crate::http::Status; -use yansi::Paint; - /// Debug prints the internal value before forwarding to the 500 error catcher. /// /// This value exists primarily to allow handler return types that would not @@ -78,8 +76,8 @@ impl From for Debug { impl<'r, E: std::fmt::Debug> Responder<'r, 'static> for Debug { fn respond_to(self, _: &'r Request<'_>) -> response::Result<'static> { - warn_!("Debug: {:?}", self.0.primary()); - warn_!("Debug always responds with {}.", Status::InternalServerError.primary()); + let type_name = std::any::type_name::(); + info!(type_name, value = ?self.0, "debug response (500)"); Err(Status::InternalServerError) } } @@ -87,7 +85,7 @@ impl<'r, E: std::fmt::Debug> Responder<'r, 'static> for Debug { /// Prints a warning with the error and forwards to the `500` error catcher. impl<'r> Responder<'r, 'static> for std::io::Error { fn respond_to(self, _: &'r Request<'_>) -> response::Result<'static> { - warn_!("I/O Error: {:?}", self.primary()); + warn!("i/o error response: {self}"); Err(Status::InternalServerError) } } diff --git a/core/lib/src/response/responder.rs b/core/lib/src/response/responder.rs index 8ff963ea..2bc14a7c 100644 --- a/core/lib/src/response/responder.rs +++ b/core/lib/src/response/responder.rs @@ -542,7 +542,10 @@ impl<'r> Responder<'r, 'static> for Status { Response::build().status(self).ok() } _ => { - error_!("Invalid status used as responder: {}.", self); + error!(status = self.code, + "invalid status used as responder\n\ + status must be one of 100, 200..=205, 400..=599"); + Err(Status::InternalServerError) } } diff --git a/core/lib/src/rocket.rs b/core/lib/src/rocket.rs index e4908bbf..5eb8c649 100644 --- a/core/lib/src/rocket.rs +++ b/core/lib/src/rocket.rs @@ -4,14 +4,14 @@ use std::sync::Arc; use std::time::Duration; use std::any::Any; use std::future::Future; +use std::panic::Location; -use yansi::Paint; use either::Either; use figment::{Figment, Provider}; use futures::TryFutureExt; use crate::shutdown::{Stages, Shutdown}; -use crate::trace::traceable::{Traceable, TraceableCollection}; +use crate::trace::{Traceable, TraceableCollection}; use crate::{sentinel, shield::Shield, Catcher, Config, Route}; use crate::listener::{Bind, DefaultListener, Endpoint, Listener}; use crate::router::Router; @@ -21,7 +21,6 @@ use crate::phase::{Stateful, StateRef, State}; use crate::http::uri::Origin; use crate::http::ext::IntoOwned; use crate::error::{Error, ErrorKind}; -// use crate::log::PaintExt; /// The application server itself. /// @@ -248,20 +247,18 @@ impl Rocket { B::Error: fmt::Display, M: Fn(&Origin<'a>, T) -> T, F: Fn(&mut Self, T), - T: Clone + fmt::Display, + T: Clone + Traceable, { let mut base = match base.clone().try_into() { Ok(origin) => origin.into_owned(), Err(e) => { - error!("invalid {} base: {}", kind, Paint::white(&base)); - error_!("{}", e); - info_!("{} {}", "in".primary(), std::panic::Location::caller()); + error!(%base, location = %Location::caller(), "invalid {kind} base uri: {e}"); panic!("aborting due to {} base error", kind); } }; if base.query().is_some() { - warn!("query in {} base '{}' is ignored", kind, Paint::white(&base)); + warn!(%base, location = %Location::caller(), "query in {kind} base is ignored"); base.clear_query(); } @@ -760,9 +757,11 @@ impl Rocket { rocket.fairings.handle_liftoff(rocket).await; if !crate::running_within_rocket_async_rt().await { - warn!("Rocket is executing inside of a custom runtime."); - info_!("Rocket's runtime is enabled via `#[rocket::main]` or `#[launch]`."); - info_!("Forced shutdown is disabled. Runtime settings may be suboptimal."); + warn!( + "Rocket is executing inside of a custom runtime.\n\ + Rocket's runtime is enabled via `#[rocket::main]` or `#[launch]`\n\ + Forced shutdown is disabled. Runtime settings may be suboptimal." + ); } tracing::info!(name: "liftoff", endpoint = %rocket.endpoints[0]); diff --git a/core/lib/src/route/route.rs b/core/lib/src/route/route.rs index e78275b9..e4e0c859 100644 --- a/core/lib/src/route/route.rs +++ b/core/lib/src/route/route.rs @@ -1,8 +1,6 @@ use std::fmt; use std::borrow::Cow; -use yansi::Paint; - use crate::http::{uri, Method, MediaType}; use crate::route::{Handler, RouteUri, BoxFuture}; use crate::sentinel::Sentry; @@ -343,27 +341,6 @@ impl Route { } } -impl fmt::Display for Route { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - if let Some(ref n) = self.name { - write!(f, "{}{}{} ", "(".cyan(), n.primary(), ")".cyan())?; - } - - write!(f, "{} ", self.method.green())?; - self.uri.color_fmt(f)?; - - if self.rank > 1 { - write!(f, " [{}]", self.rank.primary().bold())?; - } - - if let Some(ref format) = self.format { - write!(f, " {}", format.yellow())?; - } - - Ok(()) - } -} - impl fmt::Debug for Route { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.debug_struct("Route") diff --git a/core/lib/src/route/uri.rs b/core/lib/src/route/uri.rs index 09072ccd..0fa34b5c 100644 --- a/core/lib/src/route/uri.rs +++ b/core/lib/src/route/uri.rs @@ -238,22 +238,6 @@ impl<'a> RouteUri<'a> { // We subtract `3` because `raw_path` is never `0`: 0b0100 = 4 - 3 = 1. -((raw_weight as isize) - 3) } - - pub(crate) fn color_fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - use yansi::Paint; - - let (path, base, unmounted) = (self.uri.path(), self.base(), self.unmounted().path()); - let unmounted_part = path.strip_prefix(base.as_str()) - .map(|raw| raw.as_str()) - .unwrap_or(unmounted.as_str()); - - write!(f, "{}{}", self.base().blue().underline(), unmounted_part.blue())?; - if let Some(q) = self.unmounted().query() { - write!(f, "{}{}", "?".yellow(), q.yellow())?; - } - - Ok(()) - } } impl Metadata { diff --git a/core/lib/src/router/collider.rs b/core/lib/src/router/collider.rs index f0978e4d..d0e15ae4 100644 --- a/core/lib/src/router/collider.rs +++ b/core/lib/src/router/collider.rs @@ -226,7 +226,7 @@ mod tests { let (a, b) = (dummy_route($ranked, $m1, $p1), dummy_route($ranked, $m2, $p2)); assert! { a.collides_with(&b), - "\nroutes failed to collide:\n{} does not collide with {}\n", a, b + "\nroutes failed to collide:\n{:?} does not collide with {:?}\n", a, b } }; (ranked $($t:tt)+) => (assert_collision!(true, $($t)+)); @@ -239,7 +239,7 @@ mod tests { let (a, b) = (dummy_route($ranked, $m1, $p1), dummy_route($ranked, $m2, $p2)); assert! { !a.collides_with(&b), - "\nunexpected collision:\n{} collides with {}\n", a, b + "\nunexpected collision:\n{:?} collides with {:?}\n", a, b } }; (ranked $($t:tt)+) => (assert_no_collision!(true, $($t)+)); diff --git a/core/lib/src/router/router.rs b/core/lib/src/router/router.rs index a9fb4600..a50c24ba 100644 --- a/core/lib/src/router/router.rs +++ b/core/lib/src/router/router.rs @@ -580,10 +580,10 @@ mod test { let req_status = Status::from_code(req.0).expect("valid status"); let catcher = catcher(&router, req_status, req.1).expect("some catcher"); assert_eq!(catcher.code, expected.0, - "\nmatched {}, expected {:?} for req {:?}", catcher, expected, req); + "\nmatched {:?}, expected {:?} for req {:?}", catcher, expected, req); assert_eq!(catcher.base.path(), expected.1, - "\nmatched {}, expected {:?} for req {:?}", catcher, expected, req); + "\nmatched {:?}, expected {:?} for req {:?}", catcher, expected, req); } }) } diff --git a/core/lib/src/serde/json.rs b/core/lib/src/serde/json.rs index c46db120..d68b24f0 100644 --- a/core/lib/src/serde/json.rs +++ b/core/lib/src/serde/json.rs @@ -219,7 +219,7 @@ impl<'r, T: Serialize> Responder<'r, 'static> for Json { 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 serialize failure: {}", e); Status::InternalServerError })?; diff --git a/core/lib/src/serde/msgpack.rs b/core/lib/src/serde/msgpack.rs index 3360f998..73217d5a 100644 --- a/core/lib/src/serde/msgpack.rs +++ b/core/lib/src/serde/msgpack.rs @@ -190,7 +190,7 @@ impl<'r, T: Serialize> Responder<'r, 'static> for MsgPack { 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 serialize failure: {}", e); Status::InternalServerError })?; diff --git a/core/lib/src/server.rs b/core/lib/src/server.rs index 2d28c14e..6820dda4 100644 --- a/core/lib/src/server.rs +++ b/core/lib/src/server.rs @@ -17,7 +17,7 @@ use crate::error::log_server_error; use crate::data::{IoStream, RawStream}; use crate::util::{spawn_inspect, FutureExt, ReaderStream}; use crate::http::Status; -use crate::trace::traceable::{Traceable, TraceableCollection}; +use crate::trace::{Traceable, TraceableCollection}; type Result = std::result::Result; diff --git a/core/lib/src/shield/shield.rs b/core/lib/src/shield/shield.rs index 803b5939..905f37d3 100644 --- a/core/lib/src/shield/shield.rs +++ b/core/lib/src/shield/shield.rs @@ -5,7 +5,7 @@ use crate::{Rocket, Request, Response, Orbit, Config}; use crate::fairing::{Fairing, Info, Kind}; use crate::http::{Header, uncased::UncasedStr}; use crate::shield::*; -use crate::trace::traceable::*; +use crate::trace::*; /// A [`Fairing`] that injects browser security and privacy headers into all /// outgoing responses. @@ -59,10 +59,8 @@ use crate::trace::traceable::*; /// /// If TLS is configured and enabled when the application is launched in a /// non-debug profile, HSTS is automatically enabled with its default policy and -/// a warning is logged. -/// -/// To get rid of this warning, explicitly [`Shield::enable()`] an [`Hsts`] -/// policy. +/// a warning is logged. To get rid of this warning, explicitly +/// [`Shield::enable()`] an [`Hsts`] policy. pub struct Shield { /// Enabled policies where the key is the header name. policies: HashMap<&'static UncasedStr, Header<'static>>, @@ -193,32 +191,19 @@ impl Fairing for Shield { && rocket.figment().profile() != Config::DEBUG_PROFILE && !self.is_enabled::(); + if force_hsts { + self.force_hsts.store(true, Ordering::Release); + } + info_span!("shield" [policies = self.policies.len()] => { self.policies.values().trace_all_info(); if force_hsts { - warn!("Detected TLS-enabled liftoff without enabling HSTS."); - warn!("Shield has enabled a default HSTS policy."); - info!("To remove this warning, configure an HSTS policy."); + warn!("Detected TLS-enabled liftoff without enabling HSTS.\n\ + Shield has enabled a default HSTS policy.\n\ + To remove this warning, configure an HSTS policy."); } }) - - // trace::collection_info!("shield", force_hsts => self.polices.values(), { - // warn!("Detected TLS-enabled liftoff without enabling HSTS."); - // warn!("Shield has enabled a default HSTS policy."); - // info!("To remove this warning, configure an HSTS policy."); - // }); - - // // tracing::info_span!("shield", force_hsts).in_scope(|| { - // // self.polices.values().trace(); - // // for header in self.policies.values() { - // // info!(name: "header", name = header.name().as_str(), value = header.value()); - // // } - // - // warn!("Detected TLS-enabled liftoff without enabling HSTS."); - // warn!("Shield has enabled a default HSTS policy."); - // info!("To remove this warning, configure an HSTS policy."); - // }); } async fn on_response<'r>(&self, _: &'r Request<'_>, response: &mut Response<'r>) { @@ -226,8 +211,10 @@ impl Fairing for Shield { // the header is not already in the response. for header in self.policies.values() { if response.headers().contains(header.name()) { - warn!("Shield: response contains a '{}' header.", header.name()); - warn_!("Refusing to overwrite existing header."); + warn_span!("shield refusing to overwrite existing response header" => { + header.trace_warn(); + }); + continue } diff --git a/core/lib/src/state.rs b/core/lib/src/state.rs index 58c9c626..aa5d941d 100644 --- a/core/lib/src/state.rs +++ b/core/lib/src/state.rs @@ -200,7 +200,10 @@ impl<'r, T: Send + Sync + 'static> FromRequest<'r> for &'r State { match State::get(req.rocket()) { Some(state) => Outcome::Success(state), None => { - error_!("Attempted to retrieve unmanaged state `{}`!", type_name::()); + error!(type_name = type_name::(), + "retrieving unmanaged state\n\ + state must be managed via `rocket.manage()`"); + Outcome::Error((Status::InternalServerError, ())) } } diff --git a/core/lib/src/tls/resolver.rs b/core/lib/src/tls/resolver.rs index d7fb3967..1b5dc119 100644 --- a/core/lib/src/tls/resolver.rs +++ b/core/lib/src/tls/resolver.rs @@ -73,15 +73,12 @@ impl fairing::Fairing for Fairing { } async fn on_ignite(&self, rocket: Rocket) -> fairing::Result { - use yansi::Paint; - let result = T::init(&rocket).await; match result { Ok(resolver) => Ok(rocket.manage(Arc::new(resolver) as Arc)), Err(e) => { - let name = std::any::type_name::(); - error!("TLS resolver {} failed to initialize.", name.primary().bold()); - error_!("{e}"); + let type_name = std::any::type_name::(); + error!(type_name, reason = %e, "TLS resolver failed to initialize"); Err(rocket) } } diff --git a/core/lib/src/trace/macros.rs b/core/lib/src/trace/macros.rs index 5a0858ca..4bd759f1 100644 --- a/core/lib/src/trace/macros.rs +++ b/core/lib/src/trace/macros.rs @@ -1,43 +1,26 @@ -pub trait PaintExt: Sized { - fn emoji(self) -> yansi::Painted; -} - -impl PaintExt for &str { - /// Paint::masked(), but hidden on Windows due to broken output. See #1122. - fn emoji(self) -> yansi::Painted { - #[cfg(windows)] { yansi::Paint::new("").mask() } - #[cfg(not(windows))] { yansi::Paint::new(self).mask() } - } -} - macro_rules! declare_macro { ($($name:ident $level:ident),* $(,)?) => ( $(declare_macro!([$] $name $level);)* ); ([$d:tt] $name:ident $level:ident) => ( + #[doc(hidden)] #[macro_export] macro_rules! $name { ($d ($t:tt)*) => ($crate::tracing::$level!($d ($t)*)); } + + // pub use $name as $name; ); } -declare_macro!( - // launch_meta INFO, launch_meta_ INFO, - error error, error_ error, - info info, info_ info, - trace trace, trace_ trace, - debug debug, debug_ debug, - warn warn, warn_ warn, -); - macro_rules! declare_span_macro { ($($name:ident $level:ident),* $(,)?) => ( $(declare_span_macro!([$] $name $level);)* ); ([$d:tt] $name:ident $level:ident) => ( + #[doc(hidden)] #[macro_export] macro_rules! $name { ($n:literal $d ([ $d ($f:tt)* ])? => $in_scope:expr) => ({ @@ -45,11 +28,12 @@ macro_rules! declare_span_macro { .in_scope(|| $in_scope); }) } + + #[doc(inline)] + pub use $name as $name; ); } -declare_span_macro!(error_span ERROR, info_span INFO, trace_span TRACE, debug_span DEBUG); - macro_rules! span { ($level:expr, $($args:tt)*) => {{ match $level { @@ -67,6 +51,8 @@ macro_rules! span { }}; } +#[doc(hidden)] +#[macro_export] macro_rules! event { ($level:expr, $($args:tt)*) => {{ match $level { @@ -82,3 +68,22 @@ macro_rules! event { $crate::tracing::event!(name: $n, target: concat!("rocket::", $n), $level, $($args)*); }}; } + +#[doc(inline)] +pub use event as event; + +declare_macro!( + error error, + info info, + trace trace, + debug debug, + warn warn +); + +declare_span_macro!( + error_span ERROR, + warn_span WARN, + info_span INFO, + trace_span TRACE, + debug_span DEBUG, +); diff --git a/core/lib/src/trace/mod.rs b/core/lib/src/trace/mod.rs index 3d604fbb..82de5496 100644 --- a/core/lib/src/trace/mod.rs +++ b/core/lib/src/trace/mod.rs @@ -1,11 +1,18 @@ #[macro_use] -pub mod macros; -#[cfg(feature = "trace")] -pub mod subscriber; -pub mod level; -pub mod traceable; +mod macros; +mod traceable; -pub use traceable::Traceable; +#[cfg(feature = "trace")] +#[cfg_attr(nightly, doc(cfg(feature = "trace")))] +pub mod subscriber; + +pub(crate) mod level; + +#[doc(inline)] +pub use traceable::{Traceable, TraceableCollection}; + +#[doc(inline)] +pub use macros::*; pub fn init<'a, T: Into>>(_config: T) { #[cfg(all(feature = "trace", debug_assertions))] diff --git a/core/lib/src/trace/subscriber/common.rs b/core/lib/src/trace/subscriber/common.rs index a35be827..f9979655 100644 --- a/core/lib/src/trace/subscriber/common.rs +++ b/core/lib/src/trace/subscriber/common.rs @@ -103,15 +103,15 @@ impl RocketFmt { } } - pub fn has_message(&self, meta: &Metadata<'_>) -> bool { + pub(crate) fn has_message(&self, meta: &Metadata<'_>) -> bool { meta.fields().field("message").is_some() } - pub fn has_data_fields(&self, meta: &Metadata<'_>) -> bool { + pub(crate) fn has_data_fields(&self, meta: &Metadata<'_>) -> bool { meta.fields().iter().any(|f| f.name() != "message") } - pub fn message<'a, F: RecordFields + 'a>(&self, + pub(crate) fn message<'a, F: RecordFields + 'a>(&self, init_prefix: &'a dyn fmt::Display, cont_prefix: &'a dyn fmt::Display, meta: &'a Metadata<'_>, @@ -142,9 +142,11 @@ impl RocketFmt { }) } - pub fn compact_fields<'a, F>(&self, meta: &'a Metadata<'_>, data: F) -> impl fmt::Display + 'a - where F: RecordFields + 'a - { + pub(crate) fn compact_fields<'a, F: RecordFields + 'a>( + &self, + meta: &'a Metadata<'_>, + data: F + ) -> impl fmt::Display + 'a { let key_style = self.style(meta).bold(); let val_style = self.style(meta).primary(); @@ -163,7 +165,7 @@ impl RocketFmt { }) } - pub fn print( + pub(crate) fn print( &self, prefix: &dyn fmt::Display, cont_prefix: &dyn fmt::Display, diff --git a/core/lib/src/trace/subscriber/mod.rs b/core/lib/src/trace/subscriber/mod.rs index d7a2e66d..ed2d71fb 100644 --- a/core/lib/src/trace/subscriber/mod.rs +++ b/core/lib/src/trace/subscriber/mod.rs @@ -4,10 +4,10 @@ mod compact; mod common; mod request_id; -pub use visit::{RecordDisplay, Data}; pub use pretty::Pretty; pub use compact::Compact; pub use common::RocketFmt; pub use request_id::{RequestId, RequestIdLayer}; pub(crate) use common::Handle; +pub(crate) use visit::{RecordDisplay, Data}; diff --git a/core/lib/src/trace/subscriber/pretty.rs b/core/lib/src/trace/subscriber/pretty.rs index 1026f61f..c020b3f4 100644 --- a/core/lib/src/trace/subscriber/pretty.rs +++ b/core/lib/src/trace/subscriber/pretty.rs @@ -151,6 +151,7 @@ impl LookupSpan<'a>> Layer for RocketFmt { "catchers" => "🚧 ", "fairings" => "📦 ", "shield" => "🛡️ ", + "templating" => "📐 ", "request" => "● ", _ => "", }; diff --git a/core/lib/src/trace/subscriber/request_id.rs b/core/lib/src/trace/subscriber/request_id.rs index b40924d1..5913476c 100644 --- a/core/lib/src/trace/subscriber/request_id.rs +++ b/core/lib/src/trace/subscriber/request_id.rs @@ -61,10 +61,10 @@ impl RequestId { impl RequestIdLayer { thread_local! { - pub static CURRENT_REQUEST_ID: Cell> = Cell::new(None); + static CURRENT_REQUEST_ID: Cell> = Cell::new(None); } - fn current() -> Option { + pub fn current() -> Option { Self::CURRENT_REQUEST_ID.get() } } diff --git a/core/lib/src/trace/traceable.rs b/core/lib/src/trace/traceable.rs index eefc4db8..e0334c0d 100644 --- a/core/lib/src/trace/traceable.rs +++ b/core/lib/src/trace/traceable.rs @@ -142,7 +142,7 @@ impl Traceable for Route { format = self.format.as_ref().map(display), } - event! { Level::DEBUG, "route", + event! { Level::DEBUG, "sentinels", route = self.name.as_ref().map(|n| &**n), sentinels = %Formatter(|f| { f.debug_set() @@ -255,8 +255,11 @@ impl Traceable for Error { impl Traceable for Sentry { fn trace(&self, level: Level) { - let (file, line, column) = self.location; - event!(level, "sentry", type_name = self.type_name, file, line, column); + let (file, line, col) = self.location; + event!(level, "sentry", + type_name = self.type_name, + location = %Formatter(|f| write!(f, "{file}:{line}:{col}")) + ); } } @@ -325,7 +328,7 @@ impl Traceable for ErrorKind { span.in_scope(|| fairings.iter().trace_all(level)); }, SentinelAborts(sentries) => { - let span = span!(level, "sentries", "sentry abort"); + let span = span!(level, "sentries", "sentry launch abort"); span.in_scope(|| sentries.iter().trace_all(level)); } InsecureSecretKey(profile) => event!(level, "insecure_key", %profile, diff --git a/examples/hello/src/main.rs b/examples/hello/src/main.rs index 3b99c310..5d66842f 100644 --- a/examples/hello/src/main.rs +++ b/examples/hello/src/main.rs @@ -1,5 +1,3 @@ -use rocket::fairing::AdHoc; - #[macro_use] extern crate rocket; #[cfg(test)] mod tests; diff --git a/examples/state/src/request_local.rs b/examples/state/src/request_local.rs index e6e1ed29..986242b7 100644 --- a/examples/state/src/request_local.rs +++ b/examples/state/src/request_local.rs @@ -21,12 +21,9 @@ impl<'r> FromRequest<'r> for Guard1 { type Error = (); async fn from_request(req: &'r Request<'_>) -> request::Outcome { - rocket::info_!("-- 1 --"); - let atomics = try_outcome!(req.guard::<&State>().await); atomics.uncached.fetch_add(1, Ordering::Relaxed); req.local_cache(|| { - rocket::info_!("1: populating cache!"); atomics.cached.fetch_add(1, Ordering::Relaxed) }); @@ -39,8 +36,6 @@ impl<'r> FromRequest<'r> for Guard2 { type Error = (); async fn from_request(req: &'r Request<'_>) -> request::Outcome { - rocket::info_!("-- 2 --"); - try_outcome!(req.guard::().await); Outcome::Success(Guard2) } @@ -51,12 +46,9 @@ impl<'r> FromRequest<'r> for Guard3 { type Error = (); async fn from_request(req: &'r Request<'_>) -> request::Outcome { - rocket::info_!("-- 3 --"); - let atomics = try_outcome!(req.guard::<&State>().await); atomics.uncached.fetch_add(1, Ordering::Relaxed); req.local_cache_async(async { - rocket::info_!("3: populating cache!"); atomics.cached.fetch_add(1, Ordering::Relaxed) }).await; @@ -69,8 +61,6 @@ impl<'r> FromRequest<'r> for Guard4 { type Error = (); async fn from_request(req: &'r Request<'_>) -> request::Outcome { - rocket::info_!("-- 4 --"); - try_outcome!(Guard3::from_request(req).await); Outcome::Success(Guard4) } diff --git a/examples/tls/src/redirector.rs b/examples/tls/src/redirector.rs index 7659da08..e38b4969 100644 --- a/examples/tls/src/redirector.rs +++ b/examples/tls/src/redirector.rs @@ -3,12 +3,12 @@ use std::net::SocketAddr; use rocket::http::Status; +use rocket::tracing::Level; use rocket::{route, Error, Request, Data, Route, Orbit, Rocket, Ignite}; use rocket::fairing::{Fairing, Info, Kind}; use rocket::response::Redirect; use rocket::listener::tcp::TcpListener; - -use yansi::Paint; +use rocket::trace::Traceable; #[derive(Debug, Clone, Copy, Default)] pub struct Redirector(u16); @@ -45,9 +45,9 @@ impl Redirector { pub async fn try_launch(self, config: Config) -> Result, Error> { use rocket::http::Method::*; - info!("{}{}", "🔒 ".mask(), "HTTP -> HTTPS Redirector:".magenta()); - info_!("redirecting insecure port {} to TLS port {}", - self.0.yellow(), config.tls_addr.port().green()); + rocket::info_span!("HTTP -> HTTPS Redirector" => { + info!(from = self.0, to = config.tls_addr.port(), "redirecting"); + }); // Build a vector of routes to `redirect` on `` for each method. let redirects = [Get, Put, Post, Delete, Options, Head, Trace, Connect, Patch] @@ -75,16 +75,18 @@ impl Fairing for Redirector { async fn on_liftoff(&self, rocket: &Rocket) { let Some(tls_addr) = rocket.endpoints().find_map(|e| e.tls()?.tcp()) else { - info!("{}{}", "🔒 ".mask(), "HTTP -> HTTPS Redirector:".magenta()); - warn_!("Main instance is not being served over TLS/TCP."); - warn_!("Redirector refusing to start."); + rocket::warn_span!("HTTP -> HTTPS Redirector" => { + warn!("Main instance is not being served over TLS/TCP.\n\ + Redirector refusing to start."); + }); + return; }; let config = Config { tls_addr, server: rocket::Config { - // log_level: LogLevel::Critical, + log_level: Some(Level::ERROR), ..rocket.config().clone() }, }; @@ -93,9 +95,11 @@ impl Fairing for Redirector { let shutdown = rocket.shutdown(); rocket::tokio::spawn(async move { if let Err(e) = this.try_launch(config).await { - error!("Failed to start HTTP -> HTTPS redirector."); - info_!("Error: {}", e); - error_!("Shutting down main instance."); + error_span!("failed to start HTTP -> HTTPS redirector" => { + e.trace_error(); + info!("shutting down main instance"); + }); + shutdown.notify(); } }); diff --git a/examples/todo/src/main.rs b/examples/todo/src/main.rs index 96763545..a12f7ab4 100644 --- a/examples/todo/src/main.rs +++ b/examples/todo/src/main.rs @@ -40,7 +40,7 @@ impl Context { match Task::all(conn).await { Ok(tasks) => Context { flash, tasks }, Err(e) => { - error_!("DB Task::all() error: {}", e); + error!("DB Task::all() error: {e}"); Context { flash: Some(("error".into(), "Fail to access database.".into())), tasks: vec![] @@ -56,7 +56,7 @@ async fn new(todo_form: Form, conn: DbConn) -> Flash { if todo.description.is_empty() { Flash::error(Redirect::to("/"), "Description cannot be empty.") } else if let Err(e) = Task::insert(todo, &conn).await { - error_!("DB insertion error: {}", e); + error!("DB insertion error: {e}"); Flash::error(Redirect::to("/"), "Todo could not be inserted due an internal error.") } else { Flash::success(Redirect::to("/"), "Todo successfully added.") @@ -68,7 +68,7 @@ async fn toggle(id: i32, conn: DbConn) -> Result { match Task::toggle_with_id(id, &conn).await { Ok(_) => Ok(Redirect::to("/")), Err(e) => { - error_!("DB toggle({}) error: {}", id, e); + error!("DB toggle({id}) error: {e}"); Err(Template::render("index", Context::err(&conn, "Failed to toggle task.").await)) } } @@ -79,7 +79,7 @@ async fn delete(id: i32, conn: DbConn) -> Result, Template> { match Task::delete_with_id(id, &conn).await { Ok(_) => Ok(Flash::success(Redirect::to("/"), "Todo was deleted.")), Err(e) => { - error_!("DB deletion({}) error: {}", id, e); + error!("DB deletion({id}) error: {e}"); Err(Template::render("index", Context::err(&conn, "Failed to delete task.").await)) } }