Log guard failures, potential misuses.

This commit includes changes that improve how and what Rocket logs
automatically. Rocket now logs:

  * All guard errors, indicating the failing guard kind and type.
  * A warning when a 'TempFile' is used as a data guard for a request
    that specifies a 'form' Content-Type.
  * Only the top/sub of a request's format.

This commit makes the following breaking changes:

  * '<T as FromData>::Error' must implement 'Debug'.

Furthermore, this commit restores the previous behavior of always
logging launch info. It further restores the unspecified behavior of
modifying logging state only when the set logger is Rocket's logger.

contrib/lib/src/lib.rs

@@ -40,7 +40,6 @@
 //! 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 rocket;
 
 #[cfg(feature="json")] #[macro_use] pub mod json;

contrib/lib/src/templates/fairing.rs

@@ -174,7 +174,7 @@ impl Fairing for TemplateFairing {
     }
 
     async fn on_liftoff(&self, rocket: &Rocket<Orbit>) {
-        use rocket::{figment::Source, logger::PaintExt, yansi::Paint};
+        use rocket::{figment::Source, log::PaintExt, yansi::Paint};
 
         let cm = rocket.state::<ContextManager>()
             .expect("Template ContextManager registered in on_ignite");

core/codegen/src/attribute/route/mod.rs

@@ -99,8 +99,8 @@ fn query_decls(route: &Route) -> Option<TokenStream> {
         )*
 
         if !_e.is_empty() {
-            #_log::warn_("query string failed to match declared route");
+            #_log::warn_!("query string failed to match declared route");
-            for _err in _e { #_log::warn_(_err); }
+            for _err in _e { #_log::warn_!("{}", _err); }
             return #Outcome::Forward(#__data);
         }
 
@@ -110,12 +110,21 @@ fn query_decls(route: &Route) -> Option<TokenStream> {
 
 fn request_guard_decl(guard: &Guard) -> TokenStream {
     let (ident, ty) = (guard.fn_ident.rocketized(), &guard.ty);
-    define_spanned_export!(ty.span() => __req, __data, _request, FromRequest, Outcome);
+    define_spanned_export!(ty.span() =>
+        __req, __data, _request, _log, FromRequest, Outcome
+    );
+
     quote_spanned! { ty.span() =>
         let #ident: #ty = match <#ty as #FromRequest>::from_request(#__req).await {
             #Outcome::Success(__v) => __v,
-            #Outcome::Forward(_) => return #Outcome::Forward(#__data),
+            #Outcome::Forward(_) => {
-            #Outcome::Failure((__c, _)) => return #Outcome::Failure(__c),
+                #_log::warn_!("`{}` request guard is forwarding.", stringify!(#ty));
+                return #Outcome::Forward(#__data);
+            },
+            #Outcome::Failure((__c, _e)) => {
+                #_log::warn_!("`{}` request guard failed: {:?}.", stringify!(#ty), _e);
+                return #Outcome::Failure(__c);
+            }
         };
     }
 }
@@ -129,7 +138,9 @@ fn param_guard_decl(guard: &Guard) -> TokenStream {
 
     // Returned when a dynamic parameter fails to parse.
     let parse_error = quote!({
-        #_log::warn_(&format!("Failed to parse '{}': {:?}", #name, __error));
+        #_log::warn_!("`{}: {}` param guard parsed forwarding with error {:?}",
+            #name, stringify!(#ty), __error);
+
         #Outcome::Forward(#__data)
     });
 
@@ -143,8 +154,9 @@ fn param_guard_decl(guard: &Guard) -> TokenStream {
                     #_Err(__error) => return #parse_error,
                 },
                 #_None => {
-                    #_log::error("Internal invariant: dynamic parameter not found.");
+                    #_log::error_!("Internal invariant broken: dyn param not found.");
-                    #_log::error("Please report this error to the Rocket issue tracker.");
+                    #_log::error_!("Please report this to the Rocket issue tracker.");
+                    #_log::error_!("https://github.com/SergioBenitez/Rocket/issues");
                     return #Outcome::Forward(#__data);
                 }
             }
@@ -163,13 +175,19 @@ fn param_guard_decl(guard: &Guard) -> TokenStream {
 
 fn data_guard_decl(guard: &Guard) -> TokenStream {
     let (ident, ty) = (guard.fn_ident.rocketized(), &guard.ty);
-    define_spanned_export!(ty.span() => __req, __data, FromData, Outcome);
+    define_spanned_export!(ty.span() => _log, __req, __data, FromData, Outcome);
 
     quote_spanned! { ty.span() =>
         let #ident: #ty = match <#ty as #FromData>::from_data(#__req, #__data).await {
             #Outcome::Success(__d) => __d,
-            #Outcome::Forward(__d) => return #Outcome::Forward(__d),
+            #Outcome::Forward(__d) => {
-            #Outcome::Failure((__c, _)) => return #Outcome::Failure(__c),
+                #_log::warn_!("`{}` data guard is forwarding.", stringify!(#ty));
+                return #Outcome::Forward(__d);
+            }
+            #Outcome::Failure((__c, _e)) => {
+                #_log::warn_!("`{}` data guard failed: {:?}.", stringify!(#ty), _e);
+                return #Outcome::Failure(__c);
+            }
         };
     }
 }

core/codegen/src/exports.rs

@@ -72,7 +72,7 @@ define_exported_paths! {
     _route => ::rocket::route,
     _catcher => ::rocket::catcher,
     _sentinel => ::rocket::sentinel,
-    _log => ::rocket::logger,
+    _log => ::rocket::log,
     _form => ::rocket::form::prelude,
     _http => ::rocket::http,
     _uri => ::rocket::http::uri,

core/lib/src/config/config.rs

@@ -285,7 +285,7 @@ impl Config {
     }
 
     pub(crate) fn pretty_print(&self, figment: &Figment) {
-        use crate::logger::PaintExt;
+        use crate::log::PaintExt;
 
         launch_info!("{}Configured for {}.", Paint::emoji("🔧 "), figment.profile());
 
@@ -443,7 +443,7 @@ pub fn pretty_print_error(error: figment::Error) {
 
     let mut config = Config::debug_default();
     config.log_level = LogLevel::Debug;
-    crate::logger::init(&config);
+    crate::log::init(&config);
 
     error!("Rocket configuration extraction from provider failed.");
     for e in error {

core/lib/src/config/mod.rs

@@ -120,7 +120,7 @@ mod secret_key;
 #[doc(hidden)] pub use config::pretty_print_error;
 
 pub use config::Config;
-pub use crate::logger::LogLevel;
+pub use crate::log::LogLevel;
 pub use tls::TlsConfig;
 
 #[cfg(feature = "secrets")]
@@ -134,7 +134,7 @@ mod tests {
     use pretty_assertions::assert_eq;
 
     use crate::config::{Config, TlsConfig};
-    use crate::logger::LogLevel;
+    use crate::log::LogLevel;
     use crate::data::{Limits, ToByteUnit};
 
     #[test]

core/lib/src/data/from_data.rs

@@ -110,6 +110,7 @@ impl<S, E> IntoOutcome<S, (Status, E), Data> for Result<S, E> {
 /// use rocket::data::{self, Data, FromData, ToByteUnit};
 /// use rocket::http::{Status, ContentType};
 ///
+/// #[derive(Debug)]
 /// enum Error {
 ///     TooLarge,
 ///     NoColon,
@@ -181,7 +182,7 @@ impl<S, E> IntoOutcome<S, (Status, E), Data> for Result<S, E> {
 #[crate::async_trait]
 pub trait FromData<'r>: Sized {
     /// The associated error to be returned when the guard fails.
-    type Error: Send;
+    type Error: Send + std::fmt::Debug;
 
     /// Asynchronously validates, parses, and converts an instance of `Self`
     /// from the incoming request body data.

core/lib/src/data/temp_file.rs

@@ -492,6 +492,16 @@ impl<'r> FromData<'r> for Capped<TempFile<'_>> {
         req: &'r crate::Request<'_>,
         data: crate::Data
     ) -> crate::data::Outcome<Self, Self::Error> {
+        use yansi::Paint;
+
+        let has_form = |ty: &ContentType| ty.is_form_data() || ty.is_form();
+        if req.content_type().map_or(false, has_form) {
+            let (tf, form) = (Paint::white("TempFile<'_>"), Paint::white("Form<TempFile<'_>>"));
+            warn!("Request contains a form that will not be processed.");
+            info_!("Bare `{}` data guard writes raw, unprocessed stream to disk.", tf);
+            info_!("Did you mean to use `{}` instead?", form);
+        }
+
         TempFile::from(req, data, None, req.content_type().cloned()).await
             .into_outcome(Status::BadRequest)
     }

core/lib/src/fairing/fairings.rs

@@ -1,6 +1,6 @@
 use crate::{Rocket, Request, Response, Data, Build, Orbit};
 use crate::fairing::{Fairing, Info, Kind};
-use crate::logger::PaintExt;
+use crate::log::PaintExt;
 
 use yansi::Paint;
 

core/lib/src/form/parser.rs

@@ -113,6 +113,7 @@ impl<'r> Iterator for RawStrParser<'r> {
             }
         };
 
+        trace_!("url-encoded field: {:?}", (name, value));
         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_one(v)),
@@ -165,7 +166,7 @@ impl<'r, 'i> MultipartParser<'r, 'i> {
         };
 
         // A field with a content-type is data; one without is "value".
-        trace_!("multipart field: {:?}", field.name());
+        trace_!("multipart field: {:?}", 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()) {

core/lib/src/lib.rs

@@ -101,12 +101,13 @@
 //!
 //! [testing chapter of the guide]: https://rocket.rs/master/guide/testing/#testing
 
-#[allow(unused_imports)] #[macro_use] extern crate rocket_codegen;
+#[macro_use]
+#[allow(unused_imports)]
+extern crate rocket_codegen;
+
 pub use rocket_codegen::*;
 pub use async_trait::*;
 
-#[macro_use] extern crate log;
-
 /// These are public dependencies! Update docs if these are changed, especially
 /// figment's version number in docs.
 #[doc(hidden)]
@@ -116,7 +117,7 @@ pub use tokio;
 pub use figment;
 
 #[doc(hidden)]
-#[macro_use] pub mod logger;
+#[macro_use] pub mod log;
 #[macro_use] pub mod outcome;
 #[macro_use] pub mod data;
 #[doc(hidden)] pub mod sentinel;
@@ -153,7 +154,6 @@ mod rocket;
 mod router;
 mod phase;
 
-#[doc(hidden)] pub use log::{info, warn, error, debug};
 #[doc(inline)] pub use crate::response::Response;
 #[doc(inline)] pub use crate::data::Data;
 #[doc(inline)] pub use crate::config::Config;

core/lib/src/log.rs

@@ -2,10 +2,38 @@
 
 use std::fmt;
 use std::str::FromStr;
+use std::sync::atomic::{AtomicBool, Ordering};
 
-use log;
-use yansi::Paint;
 use serde::{de, Serialize, Serializer, Deserialize, Deserializer};
+use yansi::Paint;
+
+/// Reexport the `log` crate as `private`.
+pub use log as private;
+
+// Expose logging macros (hidden) for use by core/contrib codegen.
+macro_rules! define_log_macro {
+    ($name:ident: $kind:ident, $target:expr, $d:tt) => (
+        #[doc(hidden)]
+        #[macro_export]
+        macro_rules! $name {
+            ($d ($t:tt)*) => ($crate::log::private::$kind!(target: $target, $d ($t)*))
+        }
+    );
+    ($kind:ident, $indented:ident) => (
+        define_log_macro!($kind: $kind, module_path!(), $);
+        define_log_macro!($indented: $kind, "_", $);
+
+        pub use $indented;
+    )
+}
+
+define_log_macro!(error, error_);
+define_log_macro!(warn, warn_);
+define_log_macro!(info, info_);
+define_log_macro!(debug, debug_);
+define_log_macro!(trace, trace_);
+define_log_macro!(launch_info: warn, "rocket::launch", $);
+define_log_macro!(launch_info_: warn, "rocket::launch_", $);
 
 #[derive(Debug)]
 struct RocketLogger;
@@ -23,6 +51,108 @@ pub enum LogLevel {
     Off,
 }
 
+pub trait PaintExt {
+    fn emoji(item: &str) -> Paint<&str>;
+}
+
+// Whether a record is a special `launch_info!` record.
+fn is_launch_record(record: &log::Metadata<'_>) -> bool {
+    record.target().contains("rocket::launch")
+}
+
+impl log::Log for RocketLogger {
+    #[inline(always)]
+    fn enabled(&self, record: &log::Metadata<'_>) -> bool {
+        match log::max_level().to_level() {
+            Some(max) => record.level() <= max || is_launch_record(record),
+            None => false
+        }
+    }
+
+    fn log(&self, record: &log::Record<'_>) {
+        // Print nothing if this level isn't enabled and this isn't launch info.
+        if !self.enabled(record.metadata()) {
+            return;
+        }
+
+        // Don't print Hyper, Rustls or r2d2 messages unless debug is enabled.
+        let max = log::max_level();
+        let from = |path| record.module_path().map_or(false, |m| m.starts_with(path));
+        let debug_only = from("hyper") || from("rustls") || from("r2d2");
+        if LogLevel::Debug.to_level_filter() > max && debug_only {
+            return;
+        }
+
+        // In Rocket, we abuse targets with suffix "_" to indicate indentation.
+        let indented = record.target().ends_with('_');
+        if indented {
+            print!("   {} ", Paint::default(">>").bold());
+        }
+
+        // Downgrade a physical launch `warn` to logical `info`.
+        let level = is_launch_record(record.metadata())
+            .then(|| log::Level::Info)
+            .unwrap_or_else(|| record.level());
+
+        match level {
+            log::Level::Error if !indented => {
+                println!("{} {}",
+                         Paint::red("Error:").bold(),
+                         Paint::red(record.args()).wrap())
+            }
+            log::Level::Warn if !indented => {
+                println!("{} {}",
+                         Paint::yellow("Warning:").bold(),
+                         Paint::yellow(record.args()).wrap())
+            }
+            log::Level::Info => println!("{}", Paint::blue(record.args()).wrap()),
+            log::Level::Trace => println!("{}", Paint::magenta(record.args()).wrap()),
+            log::Level::Warn => println!("{}", Paint::yellow(record.args()).wrap()),
+            log::Level::Error => println!("{}", Paint::red(record.args()).wrap()),
+            log::Level::Debug => {
+                print!("\n{} ", Paint::blue("-->").bold());
+                if let Some(file) = record.file() {
+                    print!("{}", Paint::blue(file));
+                }
+
+                if let Some(line) = record.line() {
+                    println!(":{}", Paint::blue(line));
+                }
+
+                println!("\t{}", record.args());
+            }
+        }
+    }
+
+    fn flush(&self) {
+        // NOOP: We don't buffer any records.
+    }
+}
+
+pub(crate) fn init(config: &crate::Config) -> bool {
+    static HAS_ROCKET_LOGGER: AtomicBool = AtomicBool::new(false);
+
+    let r = log::set_boxed_logger(Box::new(RocketLogger));
+    if r.is_ok() {
+        HAS_ROCKET_LOGGER.store(true, Ordering::Release);
+    }
+
+    // If another has been set, don't touch anything.
+    if !HAS_ROCKET_LOGGER.load(Ordering::Acquire) {
+        return false;
+    }
+
+    if !atty::is(atty::Stream::Stdout)
+        || (cfg!(windows) && !Paint::enable_windows_ascii())
+        || !config.cli_colors
+    {
+        Paint::disable();
+    }
+
+    log::set_max_level(config.log_level.to_level_filter());
+    true
+}
+
 impl LogLevel {
     fn as_str(&self) -> &str {
         match self {
@@ -33,7 +163,6 @@ impl LogLevel {
         }
     }
 
-    #[inline(always)]
     fn to_level_filter(self) -> log::LevelFilter {
         match self {
             LogLevel::Critical => log::LevelFilter::Warn,
@@ -82,109 +211,6 @@ impl<'de> Deserialize<'de> for LogLevel {
     }
 }
 
-#[doc(hidden)] #[macro_export]
-macro_rules! log_ { ($name:ident: $($args:tt)*) => { $name!(target: "_", $($args)*) }; }
-#[doc(hidden)] #[macro_export]
-macro_rules! launch_info { ($($args:tt)*) => { info!(target: "launch", $($args)*) } }
-#[doc(hidden)] #[macro_export]
-macro_rules! launch_info_ { ($($args:tt)*) => { info!(target: "launch_", $($args)*) } }
-#[doc(hidden)] #[macro_export]
-macro_rules! error_ { ($($args:expr),+) => { log_!(error: $($args),+); }; }
-#[doc(hidden)] #[macro_export]
-macro_rules! info_ { ($($args:expr),+) => { log_!(info: $($args),+); }; }
-#[doc(hidden)] #[macro_export]
-macro_rules! trace_ { ($($args:expr),+) => { log_!(trace: $($args),+); }; }
-#[doc(hidden)] #[macro_export]
-macro_rules! debug_ { ($($args:expr),+) => { log_!(debug: $($args),+); }; }
-#[doc(hidden)] #[macro_export]
-macro_rules! warn_ { ($($args:expr),+) => { log_!(warn: $($args),+); }; }
-
-impl log::Log for RocketLogger {
-    #[inline(always)]
-    fn enabled(&self, record: &log::Metadata<'_>) -> bool {
-        match log::max_level().to_level() {
-            Some(max) => record.level() <= max || record.target().starts_with("launch"),
-            None => false
-        }
-    }
-
-    fn log(&self, record: &log::Record<'_>) {
-        // Print nothing if this level isn't enabled and this isn't launch info.
-        if !self.enabled(record.metadata()) {
-            return;
-        }
-
-        // Don't print Hyper, Rustls or r2d2 messages unless debug is enabled.
-        let max = log::max_level();
-        let from = |path| record.module_path().map_or(false, |m| m.starts_with(path));
-        let debug_only = from("hyper") || from("rustls") || from("r2d2");
-        if LogLevel::Debug.to_level_filter() > max && debug_only {
-            return;
-        }
-
-        // In Rocket, we abuse targets with suffix "_" to indicate indentation.
-        let indented = record.target().ends_with('_');
-        if indented {
-            print!("   {} ", Paint::default(">>").bold());
-        }
-
-        match record.level() {
-            log::Level::Error if !indented => {
-                println!("{} {}",
-                         Paint::red("Error:").bold(),
-                         Paint::red(record.args()).wrap())
-            }
-            log::Level::Warn if !indented => {
-                println!("{} {}",
-                         Paint::yellow("Warning:").bold(),
-                         Paint::yellow(record.args()).wrap())
-            }
-            log::Level::Info => println!("{}", Paint::blue(record.args()).wrap()),
-            log::Level::Trace => println!("{}", Paint::magenta(record.args()).wrap()),
-            log::Level::Warn => println!("{}", Paint::yellow(record.args()).wrap()),
-            log::Level::Error => println!("{}", Paint::red(record.args()).wrap()),
-            log::Level::Debug => {
-                print!("\n{} ", Paint::blue("-->").bold());
-                if let Some(file) = record.file() {
-                    print!("{}", Paint::blue(file));
-                }
-
-                if let Some(line) = record.line() {
-                    println!(":{}", Paint::blue(line));
-                }
-
-                println!("\t{}", record.args());
-            }
-        }
-    }
-
-    fn flush(&self) {
-        // NOOP: We don't buffer any records.
-    }
-}
-
-pub(crate) fn init(config: &crate::Config) -> bool {
-    if !atty::is(atty::Stream::Stdout)
-        || (cfg!(windows) && !Paint::enable_windows_ascii())
-        || !config.cli_colors
-    {
-        Paint::disable();
-    }
-
-    if let Err(e) = log::set_boxed_logger(Box::new(RocketLogger)) {
-        if config.log_level == LogLevel::Debug {
-            eprintln!("Logger failed to initialize: {}", e);
-        }
-    }
-
-    log::set_max_level(config.log_level.to_level_filter());
-    true
-}
-
-pub trait PaintExt {
-    fn emoji(item: &str) -> Paint<&str>;
-}
-
 impl PaintExt for Paint<&str> {
     /// Paint::masked(), but hidden on Windows due to broken output. See #1122.
     fn emoji(_item: &str) -> Paint<&str> {
@@ -192,16 +218,3 @@ impl PaintExt for Paint<&str> {
         #[cfg(not(windows))] { Paint::masked(_item) }
     }
 }
-
-// Expose logging macros as (hidden) funcions for use by core/contrib codegen.
-macro_rules! external_log_function {
-    ($fn_name:ident: $macro_name:ident) => (
-        #[doc(hidden)] #[inline(always)]
-        pub fn $fn_name<T: std::fmt::Display>(msg: T) { $macro_name!("{}", msg); }
-    )
-}
-
-external_log_function!(error: error);
-external_log_function!(error_: error_);
-external_log_function!(warn: warn);
-external_log_function!(warn_: warn_);

core/lib/src/request/from_param.rs

@@ -1,6 +1,5 @@
 use std::str::FromStr;
 use std::path::PathBuf;
-use std::fmt::Debug;
 
 use crate::http::uri::{Segments, PathError};
 
@@ -177,7 +176,7 @@ use crate::http::uri::{Segments, PathError};
 /// ```
 pub trait FromParam<'a>: Sized {
     /// The associated error to be returned if parsing/validation fails.
-    type Error: Debug;
+    type Error: std::fmt::Debug;
 
     /// Parses and validates an instance of `Self` from a path parameter string
     /// or returns an `Error` if parsing or validation fails.
@@ -273,7 +272,7 @@ impl<'a, T: FromParam<'a>> FromParam<'a> for Option<T> {
 /// the `Utf8Error`.
 pub trait FromSegments<'r>: Sized {
     /// The associated error to be returned when parsing fails.
-    type Error: Debug;
+    type Error: std::fmt::Debug;
 
     /// Parses an instance of `Self` from many dynamic path parameter strings or
     /// returns an `Error` if one cannot be parsed.

core/lib/src/request/request.rs

@@ -925,7 +925,10 @@ impl fmt::Display for Request<'_> {
         // Print the requests media type when the route specifies a format.
         if let Some(media_type) = self.format() {
             if !media_type.is_any() {
-                write!(f, " {}", Paint::yellow(media_type))?;
+                write!(f, " {}{}{}",
+                    Paint::yellow(media_type.top()),
+                    Paint::yellow("/"),
+                    Paint::yellow(media_type.sub()))?;
             }
         }
 

core/lib/src/rocket.rs

@@ -16,7 +16,7 @@ use crate::phase::{Stateful, StateRef, State};
 use crate::http::uri::{self, Origin};
 use crate::http::ext::IntoOwned;
 use crate::error::{Error, ErrorKind};
-use crate::logger::PaintExt;
+use crate::log::PaintExt;
 
 /// The application server itself.
 ///
@@ -463,14 +463,14 @@ impl Rocket<Build> {
     pub async fn ignite(mut self) -> Result<Rocket<Ignite>, Error> {
         // We initialize the logger here so that logging from fairings are
         // visible but change the max-log-level when we have a final config.
-        crate::logger::init(&Config::debug_default());
+        crate::log::init(&Config::debug_default());
         self = Fairings::handle_ignite(self).await;
         self.fairings.audit().map_err(|f| ErrorKind::FailedFairings(f.to_vec()))?;
 
         // Extract the configuration; initialize the logger.
         #[allow(unused_mut)]
         let mut config = self.figment.extract::<Config>().map_err(ErrorKind::Config)?;
-        crate::logger::init(&config);
+        crate::log::init(&config);
 
         // Check for safely configured secrets.
         #[cfg(feature = "secrets")]

examples/cookies/Rocket.toml

@@ -1,2 +1,3 @@
-[global]
+[default]
 secret_key = "itlYmFR2vYKrOmFhupMIn/hyB6lYCCTXz4yaQX89XVg="
+template_dir = "templates"