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