src/liblog/lib.rs

   1 // Copyright 2014 The Rust Project Developers. See the COPYRIGHT
   2 // file at the top-level directory of this distribution and at
   3 // http://rust-lang.org/COPYRIGHT.
   4 //
   5 // Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
   6 // http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
   7 // <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
   8 // option. This file may not be copied, modified, or distributed
   9 // except according to those terms.
  10
  11 //! Utilities for program-wide and customizable logging
  12 //!
  13 //! # Examples
  14 //!
  15 //! ```
  16 //! #[macro_use] extern crate log;
  17 //!
  18 //! fn main() {
  19 //!     debug!("this is a debug {:?}", "message");
  20 //!     error!("this is printed by default");
  21 //!
  22 //!     if log_enabled!(log::INFO) {
  23 //!         let x = 3 * 4; // expensive computation
  24 //!         info!("the answer was: {:?}", x);
  25 //!     }
  26 //! }
  27 //! ```
  28 //!
  29 //! Assumes the binary is `main`:
  30 //!
  31 //! ```{.bash}
  32 //! $ RUST_LOG=error ./main
  33 //! ERROR:main: this is printed by default
  34 //! ```
  35 //!
  36 //! ```{.bash}
  37 //! $ RUST_LOG=info ./main
  38 //! ERROR:main: this is printed by default
  39 //! INFO:main: the answer was: 12
  40 //! ```
  41 //!
  42 //! ```{.bash}
  43 //! $ RUST_LOG=debug ./main
  44 //! DEBUG:main: this is a debug message
  45 //! ERROR:main: this is printed by default
  46 //! INFO:main: the answer was: 12
  47 //! ```
  48 //!
  49 //! You can also set the log level on a per module basis:
  50 //!
  51 //! ```{.bash}
  52 //! $ RUST_LOG=main=info ./main
  53 //! ERROR:main: this is printed by default
  54 //! INFO:main: the answer was: 12
  55 //! ```
  56 //!
  57 //! And enable all logging:
  58 //!
  59 //! ```{.bash}
  60 //! $ RUST_LOG=main ./main
  61 //! DEBUG:main: this is a debug message
  62 //! ERROR:main: this is printed by default
  63 //! INFO:main: the answer was: 12
  64 //! ```
  65 //!
  66 //! # Logging Macros
  67 //!
  68 //! There are five macros that the logging subsystem uses:
  69 //!
  70 //! * `log!(level, ...)` - the generic logging macro, takes a level as a u32 and any
  71 //!                        related `format!` arguments
  72 //! * `debug!(...)` - a macro hard-wired to the log level of `DEBUG`
  73 //! * `info!(...)` - a macro hard-wired to the log level of `INFO`
  74 //! * `warn!(...)` - a macro hard-wired to the log level of `WARN`
  75 //! * `error!(...)` - a macro hard-wired to the log level of `ERROR`
  76 //!
  77 //! All of these macros use the same style of syntax as the `format!` syntax
  78 //! extension. Details about the syntax can be found in the documentation of
  79 //! `std::fmt` along with the Rust tutorial/manual.
  80 //!
  81 //! If you want to check at runtime if a given logging level is enabled (e.g. if the
  82 //! information you would want to log is expensive to produce), you can use the
  83 //! following macro:
  84 //!
  85 //! * `log_enabled!(level)` - returns true if logging of the given level is enabled
  86 //!
  87 //! # Enabling logging
  88 //!
  89 //! Log levels are controlled on a per-module basis, and by default all logging is
  90 //! disabled except for `error!` (a log level of 1). Logging is controlled via the
  91 //! `RUST_LOG` environment variable. The value of this environment variable is a
  92 //! comma-separated list of logging directives. A logging directive is of the form:
  93 //!
  94 //! ```text
  95 //! path::to::module=log_level
  96 //! ```
  97 //!
  98 //! The path to the module is rooted in the name of the crate it was compiled for,
  99 //! so if your program is contained in a file `hello.rs`, for example, to turn on
 100 //! logging for this file you would use a value of `RUST_LOG=hello`.
 101 //! Furthermore, this path is a prefix-search, so all modules nested in the
 102 //! specified module will also have logging enabled.
 103 //!
 104 //! The actual `log_level` is optional to specify. If omitted, all logging will be
 105 //! enabled. If specified, the it must be either a numeric in the range of 1-255, or
 106 //! it must be one of the strings `debug`, `error`, `info`, or `warn`. If a numeric
 107 //! is specified, then all logging less than or equal to that numeral is enabled.
 108 //! For example, if logging level 3 is active, error, warn, and info logs will be
 109 //! printed, but debug will be omitted.
 110 //!
 111 //! As the log level for a module is optional, the module to enable logging for is
 112 //! also optional. If only a `log_level` is provided, then the global log level for
 113 //! all modules is set to this value.
 114 //!
 115 //! Some examples of valid values of `RUST_LOG` are:
 116 //!
 117 //! * `hello` turns on all logging for the 'hello' module
 118 //! * `info` turns on all info logging
 119 //! * `hello=debug` turns on debug logging for 'hello'
 120 //! * `hello=3` turns on info logging for 'hello'
 121 //! * `hello,std::option` turns on hello, and std's option logging
 122 //! * `error,hello=warn` turn on global error logging and also warn for hello
 123 //!
 124 //! # Filtering results
 125 //!
 126 //! A RUST_LOG directive may include a string filter. The syntax is to append
 127 //! `/` followed by a string. Each message is checked against the string and is
 128 //! only logged if it contains the string. Note that the matching is done after
 129 //! formatting the log string but before adding any logging meta-data. There is
 130 //! a single filter for all modules.
 131 //!
 132 //! Some examples:
 133 //!
 134 //! * `hello/foo` turns on all logging for the 'hello' module where the log message
 135 //! includes 'foo'.
 136 //! * `info/f.o` turns on all info logging where the log message includes 'foo',
 137 //! 'f1o', 'fao', etc.
 138 //! * `hello=debug/foo*foo` turns on debug logging for 'hello' where the log
 139 //! message includes 'foofoo' or 'fofoo' or 'fooooooofoo', etc.
 140 //! * `error,hello=warn/[0-9] scopes` turn on global error logging and also warn for
 141 //!  hello. In both cases the log message must include a single digit number
 142 //!  followed by 'scopes'
 143 //!
 144 //! # Performance and Side Effects
 145 //!
 146 //! Each of these macros will expand to code similar to:
 147 //!
 148 //! ```rust,ignore
 149 //! if log_level <= my_module_log_level() {
 150 //!     ::log::log(log_level, format!(...));
 151 //! }
 152 //! ```
 153 //!
 154 //! What this means is that each of these macros are very cheap at runtime if
 155 //! they're turned off (just a load and an integer comparison). This also means that
 156 //! if logging is disabled, none of the components of the log will be executed.
 157
 158 // Do not remove on snapshot creation. Needed for bootstrap. (Issue #22364)
 159 #![cfg_attr(stage0, feature(custom_attribute))]
 160 #![crate_name = "log"]
 161 #![unstable(feature = "rustc_private",
 162             reason = "use the crates.io `log` library instead")]
 163 #![staged_api]
 164 #![crate_type = "rlib"]
 165 #![crate_type = "dylib"]
 166 #![doc(html_logo_url = "http://www.rust-lang.org/logos/rust-logo-128x128-blk-v2.png",
 167        html_favicon_url = "https://doc.rust-lang.org/favicon.ico",
 168        html_root_url = "http://doc.rust-lang.org/nightly/",
 169        html_playground_url = "http://play.rust-lang.org/")]
 170 #![deny(missing_docs)]
 171
 172 #![feature(alloc)]
 173 #![feature(staged_api)]
 174 #![feature(box_syntax)]
 175 #![feature(core)]
 176 #![feature(const_fn)]
 177 #![feature(std_misc)]
 178
 179 use std::boxed;
 180 use std::cell::RefCell;
 181 use std::fmt;
 182 use std::io::{self, Stderr};
 183 use std::io::prelude::*;
 184 use std::mem;
 185 use std::env;
 186 use std::rt;
 187 use std::slice;
 188 use std::sync::{Once, StaticMutex};
 189
 190 use directive::LOG_LEVEL_NAMES;
 191
 192 #[macro_use]
 193 pub mod macros;
 194
 195 mod directive;
 196
 197 /// Maximum logging level of a module that can be specified. Common logging
 198 /// levels are found in the DEBUG/INFO/WARN/ERROR constants.
 199 pub const MAX_LOG_LEVEL: u32 = 255;
 200
 201 /// The default logging level of a crate if no other is specified.
 202 const DEFAULT_LOG_LEVEL: u32 = 1;
 203
 204 static LOCK: StaticMutex = StaticMutex::new();
 205
 206 /// An unsafe constant that is the maximum logging level of any module
 207 /// specified. This is the first line of defense to determining whether a
 208 /// logging statement should be run.
 209 static mut LOG_LEVEL: u32 = MAX_LOG_LEVEL;
 210
 211 static mut DIRECTIVES: *mut Vec<directive::LogDirective> =
 212     0 as *mut Vec<directive::LogDirective>;
 213
 214 /// Optional filter.
 215 static mut FILTER: *mut String = 0 as *mut _;
 216
 217 /// Debug log level
 218 pub const DEBUG: u32 = 4;
 219 /// Info log level
 220 pub const INFO: u32 = 3;
 221 /// Warn log level
 222 pub const WARN: u32 = 2;
 223 /// Error log level
 224 pub const ERROR: u32 = 1;
 225
 226 thread_local! {
 227     static LOCAL_LOGGER: RefCell<Option<Box<Logger + Send>>> = {
 228         RefCell::new(None)
 229     }
 230 }
 231
 232 /// A trait used to represent an interface to a thread-local logger. Each thread
 233 /// can have its own custom logger which can respond to logging messages
 234 /// however it likes.
 235 pub trait Logger {
 236     /// Logs a single message described by the `record`.
 237     fn log(&mut self, record: &LogRecord);
 238 }
 239
 240 struct DefaultLogger { handle: Stderr }
 241
 242 /// Wraps the log level with fmt implementations.
 243 #[derive(Copy, Clone, PartialEq, PartialOrd, Debug)]
 244 pub struct LogLevel(pub u32);
 245
 246 impl fmt::Display for LogLevel {
 247     fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
 248         let LogLevel(level) = *self;
 249         match LOG_LEVEL_NAMES.get(level as usize - 1) {
 250             Some(ref name) => fmt::Display::fmt(name, fmt),
 251             None => fmt::Display::fmt(&level, fmt)
 252         }
 253     }
 254 }
 255
 256 impl Logger for DefaultLogger {
 257     fn log(&mut self, record: &LogRecord) {
 258         match writeln!(&mut self.handle,
 259                        "{}:{}: {}",
 260                        record.level,
 261                        record.module_path,
 262                        record.args) {
 263             Err(e) => panic!("failed to log: {:?}", e),
 264             Ok(()) => {}
 265         }
 266     }
 267 }
 268
 269 impl Drop for DefaultLogger {
 270     fn drop(&mut self) {
 271         // FIXME(#12628): is panicking the right thing to do?
 272         match self.handle.flush() {
 273             Err(e) => panic!("failed to flush a logger: {:?}", e),
 274             Ok(()) => {}
 275         }
 276     }
 277 }
 278
 279 /// This function is called directly by the compiler when using the logging
 280 /// macros. This function does not take into account whether the log level
 281 /// specified is active or not, it will always log something if this method is
 282 /// called.
 283 ///
 284 /// It is not recommended to call this function directly, rather it should be
 285 /// invoked through the logging family of macros.
 286 #[doc(hidden)]
 287 pub fn log(level: u32, loc: &'static LogLocation, args: fmt::Arguments) {
 288     // Test the literal string from args against the current filter, if there
 289     // is one.
 290     unsafe {
 291         let _g = LOCK.lock();
 292         match FILTER as usize {
 293             0 => {}
 294             1 => panic!("cannot log after main thread has exited"),
 295             n => {
 296                 let filter = mem::transmute::<_, &String>(n);
 297                 if !args.to_string().contains(&filter[..]) {
 298                     return
 299                 }
 300             }
 301         }
 302     }
 303
 304     // Completely remove the local logger from TLS in case anyone attempts to
 305     // frob the slot while we're doing the logging. This will destroy any logger
 306     // set during logging.
 307     let mut logger: Box<Logger + Send> = LOCAL_LOGGER.with(|s| {
 308         s.borrow_mut().take()
 309     }).unwrap_or_else(|| {
 310         box DefaultLogger { handle: io::stderr() }
 311     });
 312     logger.log(&LogRecord {
 313         level: LogLevel(level),
 314         args: args,
 315         file: loc.file,
 316         module_path: loc.module_path,
 317         line: loc.line,
 318     });
 319     set_logger(logger);
 320 }
 321
 322 /// Getter for the global log level. This is a function so that it can be called
 323 /// safely
 324 #[doc(hidden)]
 325 #[inline(always)]
 326 pub fn log_level() -> u32 { unsafe { LOG_LEVEL } }
 327
 328 /// Replaces the thread-local logger with the specified logger, returning the old
 329 /// logger.
 330 pub fn set_logger(logger: Box<Logger + Send>) -> Option<Box<Logger + Send>> {
 331     let mut l = Some(logger);
 332     LOCAL_LOGGER.with(|slot| {
 333         mem::replace(&mut *slot.borrow_mut(), l.take())
 334     })
 335 }
 336
 337 /// A LogRecord is created by the logging macros, and passed as the only
 338 /// argument to Loggers.
 339 #[derive(Debug)]
 340 pub struct LogRecord<'a> {
 341
 342     /// The module path of where the LogRecord originated.
 343     pub module_path: &'a str,
 344
 345     /// The LogLevel of this record.
 346     pub level: LogLevel,
 347
 348     /// The arguments from the log line.
 349     pub args: fmt::Arguments<'a>,
 350
 351     /// The file of where the LogRecord originated.
 352     pub file: &'a str,
 353
 354     /// The line number of where the LogRecord originated.
 355     pub line: u32,
 356 }
 357
 358 #[doc(hidden)]
 359 #[derive(Copy, Clone)]
 360 pub struct LogLocation {
 361     pub module_path: &'static str,
 362     pub file: &'static str,
 363     pub line: u32,
 364 }
 365
 366 /// Tests whether a given module's name is enabled for a particular level of
 367 /// logging. This is the second layer of defense about determining whether a
 368 /// module's log statement should be emitted or not.
 369 #[doc(hidden)]
 370 pub fn mod_enabled(level: u32, module: &str) -> bool {
 371     static INIT: Once = Once::new();
 372     INIT.call_once(init);
 373
 374     // It's possible for many threads are in this function, only one of them
 375     // will perform the global initialization, but all of them will need to check
 376     // again to whether they should really be here or not. Hence, despite this
 377     // check being expanded manually in the logging macro, this function checks
 378     // the log level again.
 379     if level > unsafe { LOG_LEVEL } { return false }
 380
 381     // This assertion should never get tripped unless we're in an at_exit
 382     // handler after logging has been torn down and a logging attempt was made.
 383
 384     let _g = LOCK.lock();
 385     unsafe {
 386         assert!(DIRECTIVES as usize != 0);
 387         assert!(DIRECTIVES as usize != 1,
 388                 "cannot log after the main thread has exited");
 389
 390         enabled(level, module, (*DIRECTIVES).iter())
 391     }
 392 }
 393
 394 fn enabled(level: u32,
 395            module: &str,
 396            iter: slice::Iter<directive::LogDirective>)
 397            -> bool {
 398     // Search for the longest match, the vector is assumed to be pre-sorted.
 399     for directive in iter.rev() {
 400         match directive.name {
 401             Some(ref name) if !module.starts_with(&name[..]) => {},
 402             Some(..) | None => {
 403                 return level <= directive.level
 404             }
 405         }
 406     }
 407     level <= DEFAULT_LOG_LEVEL
 408 }
 409
 410 /// Initialize logging for the current process.
 411 ///
 412 /// This is not threadsafe at all, so initialization is performed through a
 413 /// `Once` primitive (and this function is called from that primitive).
 414 fn init() {
 415     let (mut directives, filter) = match env::var("RUST_LOG") {
 416         Ok(spec) => directive::parse_logging_spec(&spec[..]),
 417         Err(..) => (Vec::new(), None),
 418     };
 419
 420     // Sort the provided directives by length of their name, this allows a
 421     // little more efficient lookup at runtime.
 422     directives.sort_by(|a, b| {
 423         let alen = a.name.as_ref().map(|a| a.len()).unwrap_or(0);
 424         let blen = b.name.as_ref().map(|b| b.len()).unwrap_or(0);
 425         alen.cmp(&blen)
 426     });
 427
 428     let max_level = {
 429         let max = directives.iter().max_by(|d| d.level);
 430         max.map(|d| d.level).unwrap_or(DEFAULT_LOG_LEVEL)
 431     };
 432
 433     unsafe {
 434         LOG_LEVEL = max_level;
 435
 436         assert!(FILTER.is_null());
 437         match filter {
 438             Some(f) => FILTER = boxed::into_raw(box f),
 439             None => {}
 440         }
 441
 442         assert!(DIRECTIVES.is_null());
 443         DIRECTIVES = boxed::into_raw(box directives);
 444
 445         // Schedule the cleanup for the globals for when the runtime exits.
 446         let _ = rt::at_exit(move || {
 447             let _g = LOCK.lock();
 448             assert!(!DIRECTIVES.is_null());
 449             let _directives = Box::from_raw(DIRECTIVES);
 450             DIRECTIVES = 1 as *mut _;
 451
 452             if !FILTER.is_null() {
 453                 let _filter = Box::from_raw(FILTER);
 454                 FILTER = 1 as *mut _;
 455             }
 456         });
 457     }
 458 }
 459
 460 #[cfg(test)]
 461 mod tests {
 462     use super::enabled;
 463     use directive::LogDirective;
 464
 465     #[test]
 466     fn match_full_path() {
 467         let dirs = [
 468             LogDirective {
 469                 name: Some("crate2".to_string()),
 470                 level: 3
 471             },
 472             LogDirective {
 473                 name: Some("crate1::mod1".to_string()),
 474                 level: 2
 475             }
 476         ];
 477         assert!(enabled(2, "crate1::mod1", dirs.iter()));
 478         assert!(!enabled(3, "crate1::mod1", dirs.iter()));
 479         assert!(enabled(3, "crate2", dirs.iter()));
 480         assert!(!enabled(4, "crate2", dirs.iter()));
 481     }
 482
 483     #[test]
 484     fn no_match() {
 485         let dirs = [
 486             LogDirective { name: Some("crate2".to_string()), level: 3 },
 487             LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
 488         ];
 489         assert!(!enabled(2, "crate3", dirs.iter()));
 490     }
 491
 492     #[test]
 493     fn match_beginning() {
 494         let dirs = [
 495             LogDirective { name: Some("crate2".to_string()), level: 3 },
 496             LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
 497         ];
 498         assert!(enabled(3, "crate2::mod1", dirs.iter()));
 499     }
 500
 501     #[test]
 502     fn match_beginning_longest_match() {
 503         let dirs = [
 504             LogDirective { name: Some("crate2".to_string()), level: 3 },
 505             LogDirective { name: Some("crate2::mod".to_string()), level: 4 },
 506             LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
 507         ];
 508         assert!(enabled(4, "crate2::mod1", dirs.iter()));
 509         assert!(!enabled(4, "crate2", dirs.iter()));
 510     }
 511
 512     #[test]
 513     fn match_default() {
 514         let dirs = [
 515             LogDirective { name: None, level: 3 },
 516             LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
 517         ];
 518         assert!(enabled(2, "crate1::mod1", dirs.iter()));
 519         assert!(enabled(3, "crate2::mod2", dirs.iter()));
 520     }
 521
 522     #[test]
 523     fn zero_level() {
 524         let dirs = [
 525             LogDirective { name: None, level: 3 },
 526             LogDirective { name: Some("crate1::mod1".to_string()), level: 0 }
 527         ];
 528         assert!(!enabled(1, "crate1::mod1", dirs.iter()));
 529         assert!(enabled(3, "crate2::mod2", dirs.iter()));
 530     }
 531 }