Dynamically increase/decrease log level at launch.

This commit modifies the internal logger so that launch messages are
emitted with the proper "info" level. The approach is to temporarily
weaken the log level to "normal" during launch and reset it to the
user's setting after launching.

This commit also upgrades to 'log' 0.4.

Fixes #553.

codegen/Cargo.toml

@@ -17,7 +17,7 @@ plugin = true
 [dependencies]
 rocket = { version = "0.4.0-dev", path = "../lib/" }
 ordermap = "0.3"
-log = "0.3"
+log = "0.4"
 
 [dev-dependencies]
 compiletest_rs = "0.3.5"

contrib/Cargo.toml

@@ -22,7 +22,7 @@ templates = ["serde", "serde_json", "glob"]
 
 [dependencies]
 rocket = { version = "0.4.0-dev", path = "../lib/" }
-log = "^0.3"
+log = "0.4"
 
 # UUID dependencies.
 uuid = { version = "^0.5", optional = true }

lib/Cargo.toml

@@ -19,7 +19,7 @@ tls = ["rustls", "hyper-sync-rustls"]
 
 [dependencies]
 yansi = { version = "0.3.3", features = ["nightly"] }
-log = "0.3"
+log = "0.4"
 percent-encoding = "1"
 toml = "0.4.2"
 num_cpus = "1.0"

lib/src/logger.rs

@@ -3,7 +3,7 @@
 use std::str::FromStr;
 use std::fmt;
 
-use log::{self, Log, LogLevel, LogRecord, LogMetadata};
+use log;
 use yansi::Paint;
 
 struct RocketLogger(LoggingLevel);
@@ -21,11 +21,11 @@ pub enum LoggingLevel {
 
 impl LoggingLevel {
     #[inline(always)]
-    fn max_log_level(&self) -> LogLevel {
+    fn max_log_level(&self) -> log::Level {
         match *self {
-            LoggingLevel::Critical => LogLevel::Warn,
-            LoggingLevel::Normal => LogLevel::Info,
-            LoggingLevel::Debug => LogLevel::Trace,
+            LoggingLevel::Critical => log::Level::Warn,
+            LoggingLevel::Normal => log::Level::Info,
+            LoggingLevel::Debug => log::Level::Trace,
         }
     }
 }
@@ -60,9 +60,9 @@ impl fmt::Display for LoggingLevel {
 #[doc(hidden)] #[macro_export]
 macro_rules! log_ { ($name:ident: $($args:tt)*) => { $name!(target: "_", $($args)*) }; }
 #[doc(hidden)] #[macro_export]
-macro_rules! launch_info { ($($args:tt)*) => { error!(target: "launch", $($args)*) } }
+macro_rules! launch_info { ($($args:tt)*) => { info!(target: "launch", $($args)*) } }
 #[doc(hidden)] #[macro_export]
-macro_rules! launch_info_ { ($($args:tt)*) => { error!(target: "launch_", $($args)*) } }
+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]
@@ -74,82 +74,102 @@ macro_rules! debug_ { ($($args:expr),+) => { log_!(debug: $($args),+); }; }
 #[doc(hidden)] #[macro_export]
 macro_rules! warn_ { ($($args:expr),+) => { log_!(warn: $($args),+); }; }
 
-impl Log for RocketLogger {
+impl log::Log for RocketLogger {
     #[inline(always)]
-    fn enabled(&self, md: &LogMetadata) -> bool {
-        md.level() <= self.0.max_log_level()
+    fn enabled(&self, record: &log::Metadata) -> bool {
+        record.target().starts_with("launch") || record.level() <= self.0.max_log_level()
     }
 
-    fn log(&self, record: &LogRecord) {
-        // Print nothing if this level isn't enabled.
+    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;
         }
 
-        // We use the `launch_info` macro to "fake" a high priority info
-        // message. We want to print the message unless the user uses a custom
-        // drain, so we set it's status to critical, but reset it here to info.
-        let (configged_level, level) = match record.target() {
-            "launch" | "launch_" => (LoggingLevel::Normal, LogLevel::Info),
-            _ => (self.0, record.level())
-        };
-
         // Don't print Hyper or Rustls messages unless debug is enabled.
-        let from_hyper = record.location().module_path().starts_with("hyper::");
-        let from_rustls = record.location().module_path().starts_with("rustls::");
+        let configged_level = self.0;
+        let from_hyper = record.module_path().map_or(false, |m| m.starts_with("hyper::"));
+        let from_rustls = record.module_path().map_or(false, |m| m.starts_with("rustls::"));
         if configged_level != LoggingLevel::Debug && (from_hyper || from_rustls) {
             return;
         }
 
-        // In Rocket, we abuse targets with value "_" to indicate indentation.
-        if record.target().ends_with('_') && configged_level != LoggingLevel::Critical {
-            print!("    {} ", Paint::white("=>"));
+        // In Rocket, we abuse targets with suffix "_" to indicate indentation.
+        if record.target().ends_with('_') {
+            if configged_level != LoggingLevel::Critical || record.target().starts_with("launch") {
+                print!("    {} ", Paint::white("=>"));
+            }
         }
 
-        use log::LogLevel::*;
-        match level {
-            Info => println!("{}", Paint::blue(record.args())),
-            Trace => println!("{}", Paint::purple(record.args())),
-            Error => {
+        match record.level() {
+            log::Level::Info => println!("{}", Paint::blue(record.args())),
+            log::Level::Trace => println!("{}", Paint::purple(record.args())),
+            log::Level::Error => {
                 println!("{} {}",
                          Paint::red("Error:").bold(),
                          Paint::red(record.args()))
             }
-            Warn => {
+            log::Level::Warn => {
                 println!("{} {}",
                          Paint::yellow("Warning:").bold(),
                          Paint::yellow(record.args()))
             }
-            Debug => {
-                let loc = record.location();
+            log::Level::Debug => {
                 print!("\n{} ", Paint::blue("-->").bold());
-                println!("{}:{}", Paint::blue(loc.file()), Paint::blue(loc.line()));
+                if let Some(file) = record.file() {
+                    print!("{}", Paint::blue(file));
+                }
+
+                if let Some(line) = record.line() {
+                    println!(":{}", Paint::blue(line));
+                }
+
                 println!("{}", record.args());
             }
         }
     }
+
+    fn flush(&self) {
+        // NOOP: We don't buffer any records.
+    }
 }
 
-#[doc(hidden)]
-pub fn try_init(level: LoggingLevel, verbose: bool) {
+pub(crate) fn try_init(level: LoggingLevel, verbose: bool) {
     if !::isatty::stdout_isatty() {
         Paint::disable();
     } else if cfg!(windows) {
         Paint::enable_windows_ascii();
     }
 
-    let result = log::set_logger(|max_log_level| {
-        max_log_level.set(level.max_log_level().to_log_level_filter());
-        Box::new(RocketLogger(level))
-    });
-
-    if let Err(err) = result {
+    push_max_level(level);
+    if let Err(e) = log::set_boxed_logger(Box::new(RocketLogger(level))) {
         if verbose {
-            println!("Logger failed to initialize: {}", err);
+            eprintln!("Logger failed to initialize: {}", e);
         }
     }
 }
 
+use std::sync::atomic::{AtomicUsize, Ordering};
+
+static LAST_LOG_FILTER: AtomicUsize = AtomicUsize::new(filter_to_usize(log::LevelFilter::Off));
+
+const fn filter_to_usize(filter: log::LevelFilter) -> usize {
+    filter as usize
+}
+
+fn usize_to_filter(num: usize) -> log::LevelFilter {
+    unsafe { ::std::mem::transmute(num) }
+}
+
+pub(crate) fn push_max_level(level: LoggingLevel) {
+    LAST_LOG_FILTER.store(filter_to_usize(log::max_level()), Ordering::Release);
+    log::set_max_level(level.max_log_level().to_level_filter());
+}
+
+pub(crate) fn pop_max_level() {
+    log::set_max_level(usize_to_filter(LAST_LOG_FILTER.load(Ordering::Acquire)));
+}
+
 #[doc(hidden)]
 pub fn init(level: LoggingLevel) {
     try_init(level, true)

lib/src/rocket.rs

@@ -372,7 +372,9 @@ impl Rocket {
     #[inline]
     fn configured(config: Config, log: bool) -> Rocket {
         if log {
+            // Initialize logger. Temporary weaken log level for launch info.
             logger::try_init(config.log_level, false);
+            logger::push_max_level(logger::LoggingLevel::Normal);
         }
 
         launch_info!("{}Configured for {}.", Paint::masked("🔧  "), config.environment);
@@ -679,6 +681,9 @@ impl Rocket {
                          Paint::white(proto).bold(),
                          Paint::white(&full_addr).bold());
 
+            // Restore the log level back to what it originally was.
+            logger::pop_max_level();
+
             let threads = self.config.workers as usize;
             if let Err(e) = server.handle_threads(self, threads) {
                 return LaunchError::from(e);