1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
// Copyright 2014 The Rust Project Developers. See the COPYRIGHT
// file at the top-level directory of this distribution and at
// http://rust-lang.org/COPYRIGHT.
//
// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
// option. This file may not be copied, modified, or distributed
// except according to those terms.

//! Utilities for program-wide and customizable logging
//!
//! ## Example
//!
//! ```
//! #[macro_use] extern crate log;
//!
//! fn main() {
//!     debug!("this is a debug {}", "message");
//!     error!("this is printed by default");
//!
//!     if log_enabled!(log::INFO) {
//!         let x = 3i * 4i; // expensive computation
//!         info!("the answer was: {}", x);
//!     }
//! }
//! ```
//!
//! Assumes the binary is `main`:
//!
//! ```{.bash}
//! $ RUST_LOG=error ./main
//! ERROR:main: this is printed by default
//! ```
//!
//! ```{.bash}
//! $ RUST_LOG=info ./main
//! ERROR:main: this is printed by default
//! INFO:main: the answer was: 12
//! ```
//!
//! ```{.bash}
//! $ RUST_LOG=debug ./main
//! DEBUG:main: this is a debug message
//! ERROR:main: this is printed by default
//! INFO:main: the answer was: 12
//! ```
//!
//! You can also set the log level on a per module basis:
//!
//! ```{.bash}
//! $ RUST_LOG=main=info ./main
//! ERROR:main: this is printed by default
//! INFO:main: the answer was: 12
//! ```
//!
//! And enable all logging:
//!
//! ```{.bash}
//! $ RUST_LOG=main ./main
//! DEBUG:main: this is a debug message
//! ERROR:main: this is printed by default
//! INFO:main: the answer was: 12
//! ```
//!
//!
//! ## Logging Macros
//!
//! There are five macros that the logging subsystem uses:
//!
//! * `log!(level, ...)` - the generic logging macro, takes a level as a u32 and any
//!                        related `format!` arguments
//! * `debug!(...)` - a macro hard-wired to the log level of `DEBUG`
//! * `info!(...)` - a macro hard-wired to the log level of `INFO`
//! * `warn!(...)` - a macro hard-wired to the log level of `WARN`
//! * `error!(...)` - a macro hard-wired to the log level of `ERROR`
//!
//! All of these macros use the same style of syntax as the `format!` syntax
//! extension. Details about the syntax can be found in the documentation of
//! `std::fmt` along with the Rust tutorial/manual.
//!
//! If you want to check at runtime if a given logging level is enabled (e.g. if the
//! information you would want to log is expensive to produce), you can use the
//! following macro:
//!
//! * `log_enabled!(level)` - returns true if logging of the given level is enabled
//!
//! ## Enabling logging
//!
//! Log levels are controlled on a per-module basis, and by default all logging is
//! disabled except for `error!` (a log level of 1). Logging is controlled via the
//! `RUST_LOG` environment variable. The value of this environment variable is a
//! comma-separated list of logging directives. A logging directive is of the form:
//!
//! ```text
//! path::to::module=log_level
//! ```
//!
//! The path to the module is rooted in the name of the crate it was compiled for,
//! so if your program is contained in a file `hello.rs`, for example, to turn on
//! logging for this file you would use a value of `RUST_LOG=hello`.
//! Furthermore, this path is a prefix-search, so all modules nested in the
//! specified module will also have logging enabled.
//!
//! The actual `log_level` is optional to specify. If omitted, all logging will be
//! enabled. If specified, the it must be either a numeric in the range of 1-255, or
//! it must be one of the strings `debug`, `error`, `info`, or `warn`. If a numeric
//! is specified, then all logging less than or equal to that numeral is enabled.
//! For example, if logging level 3 is active, error, warn, and info logs will be
//! printed, but debug will be omitted.
//!
//! As the log level for a module is optional, the module to enable logging for is
//! also optional. If only a `log_level` is provided, then the global log level for
//! all modules is set to this value.
//!
//! Some examples of valid values of `RUST_LOG` are:
//!
//! * `hello` turns on all logging for the 'hello' module
//! * `info` turns on all info logging
//! * `hello=debug` turns on debug logging for 'hello'
//! * `hello=3` turns on info logging for 'hello'
//! * `hello,std::option` turns on hello, and std's option logging
//! * `error,hello=warn` turn on global error logging and also warn for hello
//!
//! ## Filtering results
//!
//! A RUST_LOG directive may include a regex filter. The syntax is to append `/`
//! followed by a regex. Each message is checked against the regex, and is only
//! logged if it matches. Note that the matching is done after formatting the log
//! string but before adding any logging meta-data. There is a single filter for all
//! modules.
//!
//! Some examples:
//!
//! * `hello/foo` turns on all logging for the 'hello' module where the log message
//! includes 'foo'.
//! * `info/f.o` turns on all info logging where the log message includes 'foo',
//! 'f1o', 'fao', etc.
//! * `hello=debug/foo*foo` turns on debug logging for 'hello' where the log
//! message includes 'foofoo' or 'fofoo' or 'fooooooofoo', etc.
//! * `error,hello=warn/[0-9] scopes` turn on global error logging and also warn for
//!  hello. In both cases the log message must include a single digit number
//!  followed by 'scopes'
//!
//! ## Performance and Side Effects
//!
//! Each of these macros will expand to code similar to:
//!
//! ```rust,ignore
//! if log_level <= my_module_log_level() {
//!     ::log::log(log_level, format!(...));
//! }
//! ```
//!
//! What this means is that each of these macros are very cheap at runtime if
//! they're turned off (just a load and an integer comparison). This also means that
//! if logging is disabled, none of the components of the log will be executed.

#![doc(html_logo_url = "http://www.rust-lang.org/logos/rust-logo-128x128-blk-v2.png",
       html_favicon_url = "http://www.rust-lang.org/favicon.ico",
       html_root_url = "http://doc.rust-lang.org/log/")]
#![deny(missing_docs)]
#![cfg_attr(test, deny(warnings))]
#![allow(unstable)]

extern crate regex;

use std::cell::RefCell;
use std::fmt;
use std::io::LineBufferedWriter;
use std::io;
use std::mem;
use std::os;
use std::rt;
use std::slice;
use std::sync::{Once, ONCE_INIT};

use regex::Regex;

use directive::LOG_LEVEL_NAMES;

#[macro_use]
pub mod macros;
mod directive;

/// Maximum logging level of a module that can be specified. Common logging
/// levels are found in the DEBUG/INFO/WARN/ERROR constants.
pub const MAX_LOG_LEVEL: u32 = 255;

/// The default logging level of a crate if no other is specified.
const DEFAULT_LOG_LEVEL: u32 = 1;

/// An unsafe constant that is the maximum logging level of any module
/// specified. This is the first line of defense to determining whether a
/// logging statement should be run.
static mut LOG_LEVEL: u32 = MAX_LOG_LEVEL;

static mut DIRECTIVES: *const Vec<directive::LogDirective> =
    0 as *const Vec<directive::LogDirective>;

/// Optional regex filter.
static mut FILTER: *const Regex = 0 as *const _;

/// Debug log level
pub const DEBUG: u32 = 4;
/// Info log level
pub const INFO: u32 = 3;
/// Warn log level
pub const WARN: u32 = 2;
/// Error log level
pub const ERROR: u32 = 1;

thread_local!(static LOCAL_LOGGER: RefCell<Option<Box<Logger + Send>>> = {
    RefCell::new(None)
});

/// A trait used to represent an interface to a task-local logger. Each task
/// can have its own custom logger which can respond to logging messages
/// however it likes.
pub trait Logger {
    /// Logs a single message described by the `record`.
    fn log(&mut self, record: &LogRecord);
}

struct DefaultLogger {
    handle: LineBufferedWriter<io::stdio::StdWriter>,
}

/// Wraps the log level with fmt implementations.
#[derive(PartialEq, PartialOrd, Show)]
pub struct LogLevel(pub u32);

impl Copy for LogLevel {}

impl fmt::String for LogLevel {
    fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
        let LogLevel(level) = *self;
        match LOG_LEVEL_NAMES.get(level as usize - 1) {
            Some(name) => name.fmt(fmt),
            None => level.fmt(fmt)
        }
    }
}

impl Logger for DefaultLogger {
    fn log(&mut self, record: &LogRecord) {
        match writeln!(&mut self.handle,
                       "{}:{}: {}",
                       record.level,
                       record.module_path,
                       record.args) {
            Err(e) => panic!("failed to log: {}", e),
            Ok(()) => {}
        }
    }
}

impl Drop for DefaultLogger {
    fn drop(&mut self) {
        // FIXME(#12628): is panicking the right thing to do?
        match self.handle.flush() {
            Err(e) => panic!("failed to flush a logger: {}", e),
            Ok(()) => {}
        }
    }
}

/// This function is called directly by the compiler when using the logging
/// macros. This function does not take into account whether the log level
/// specified is active or not, it will always log something if this method is
/// called.
///
/// It is not recommended to call this function directly, rather it should be
/// invoked through the logging family of macros.
#[doc(hidden)]
pub fn log(level: u32, loc: &'static LogLocation, args: fmt::Arguments) {
    // Test the literal string from args against the current filter, if there
    // is one.
    match unsafe { FILTER.as_ref() } {
        Some(filter) if !filter.is_match(args.to_string().as_slice()) => return,
        _ => {}
    }

    // Completely remove the local logger from TLS in case anyone attempts to
    // frob the slot while we're doing the logging. This will destroy any logger
    // set during logging.
    let mut logger = LOCAL_LOGGER.with(|s| {
        s.borrow_mut().take()
    }).unwrap_or_else(|| {
        Box::new(DefaultLogger { handle: io::stderr() }) as Box<Logger + Send>
    });
    logger.log(&LogRecord {
        level: LogLevel(level),
        args: args,
        file: loc.file,
        module_path: loc.module_path,
        line: loc.line,
    });
    set_logger(logger);
}

/// Getter for the global log level. This is a function so that it can be called
/// safely
#[doc(hidden)]
#[inline(always)]
pub fn log_level() -> u32 { unsafe { LOG_LEVEL } }

/// Replaces the task-local logger with the specified logger, returning the old
/// logger.
pub fn set_logger(logger: Box<Logger + Send>) -> Option<Box<Logger + Send>> {
    let mut l = Some(logger);
    LOCAL_LOGGER.with(|slot| {
        mem::replace(&mut *slot.borrow_mut(), l.take())
    })
}

/// A LogRecord is created by the logging macros, and passed as the only
/// argument to Loggers.
#[derive(Show)]
pub struct LogRecord<'a> {

    /// The module path of where the LogRecord originated.
    pub module_path: &'a str,

    /// The LogLevel of this record.
    pub level: LogLevel,

    /// The arguments from the log line.
    pub args: fmt::Arguments<'a>,

    /// The file of where the LogRecord originated.
    pub file: &'a str,

    /// The line number of where the LogRecord originated.
    pub line: usize,
}

#[doc(hidden)]
pub struct LogLocation {
    pub module_path: &'static str,
    pub file: &'static str,
    pub line: usize,
}

impl Copy for LogLocation {}

/// Tests whether a given module's name is enabled for a particular level of
/// logging. This is the second layer of defense about determining whether a
/// module's log statement should be emitted or not.
#[doc(hidden)]
pub fn mod_enabled(level: u32, module: &str) -> bool {
    static INIT: Once = ONCE_INIT;
    INIT.call_once(init);

    // It's possible for many threads are in this function, only one of them
    // will perform the global initialization, but all of them will need to check
    // again to whether they should really be here or not. Hence, despite this
    // check being expanded manually in the logging macro, this function checks
    // the log level again.
    if level > unsafe { LOG_LEVEL } { return false }

    // This assertion should never get tripped unless we're in an at_exit
    // handler after logging has been torn down and a logging attempt was made.
    assert!(unsafe { !DIRECTIVES.is_null() });

    enabled(level, module, unsafe { (*DIRECTIVES).iter() })
}

fn enabled(level: u32,
           module: &str,
           iter: slice::Iter<directive::LogDirective>)
           -> bool {
    // Search for the longest match, the vector is assumed to be pre-sorted.
    for directive in iter.rev() {
        match directive.name {
            Some(ref name) if !module.starts_with(name.as_slice()) => {},
            Some(..) | None => {
                return level <= directive.level
            }
        }
    }
    level <= DEFAULT_LOG_LEVEL
}

/// Initialize logging for the current process.
///
/// This is not threadsafe at all, so initialization is performed through a
/// `Once` primitive (and this function is called from that primitive).
fn init() {
    let (mut directives, filter) = match os::getenv("RUST_LOG") {
        Some(spec) => directive::parse_logging_spec(spec.as_slice()),
        None => (Vec::new(), None),
    };

    // Sort the provided directives by length of their name, this allows a
    // little more efficient lookup at runtime.
    directives.sort_by(|a, b| {
        let alen = a.name.as_ref().map(|a| a.len()).unwrap_or(0);
        let blen = b.name.as_ref().map(|b| b.len()).unwrap_or(0);
        alen.cmp(&blen)
    });

    let max_level = {
        let max = directives.iter().max_by(|d| d.level);
        max.map(|d| d.level).unwrap_or(DEFAULT_LOG_LEVEL)
    };

    unsafe {
        LOG_LEVEL = max_level;

        assert!(FILTER.is_null());
        match filter {
            Some(f) => FILTER = mem::transmute(Box::new(f)),
            None => {}
        }

        assert!(DIRECTIVES.is_null());
        DIRECTIVES = mem::transmute(Box::new(directives));

        // Schedule the cleanup for the globals for when the runtime exits.
        rt::at_exit(|| {
            assert!(!DIRECTIVES.is_null());
            let _directives: Box<Vec<directive::LogDirective>> =
                mem::transmute(DIRECTIVES);
            DIRECTIVES = 0 as *const Vec<directive::LogDirective>;

            if !FILTER.is_null() {
                let _filter: Box<Regex> = mem::transmute(FILTER);
                FILTER = 0 as *const _;
            }
        });
    }
}

#[cfg(test)]
mod tests {
    use super::enabled;
    use directive::LogDirective;

    #[test]
    fn match_full_path() {
        let dirs = [
            LogDirective {
                name: Some("crate2".to_string()),
                level: 3
            },
            LogDirective {
                name: Some("crate1::mod1".to_string()),
                level: 2
            }
        ];
        assert!(enabled(2, "crate1::mod1", dirs.iter()));
        assert!(!enabled(3, "crate1::mod1", dirs.iter()));
        assert!(enabled(3, "crate2", dirs.iter()));
        assert!(!enabled(4, "crate2", dirs.iter()));
    }

    #[test]
    fn no_match() {
        let dirs = [
            LogDirective { name: Some("crate2".to_string()), level: 3 },
            LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
        ];
        assert!(!enabled(2, "crate3", dirs.iter()));
    }

    #[test]
    fn match_beginning() {
        let dirs = [
            LogDirective { name: Some("crate2".to_string()), level: 3 },
            LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
        ];
        assert!(enabled(3, "crate2::mod1", dirs.iter()));
    }

    #[test]
    fn match_beginning_longest_match() {
        let dirs = [
            LogDirective { name: Some("crate2".to_string()), level: 3 },
            LogDirective { name: Some("crate2::mod".to_string()), level: 4 },
            LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
        ];
        assert!(enabled(4, "crate2::mod1", dirs.iter()));
        assert!(!enabled(4, "crate2", dirs.iter()));
    }

    #[test]
    fn match_default() {
        let dirs = [
            LogDirective { name: None, level: 3 },
            LogDirective { name: Some("crate1::mod1".to_string()), level: 2 }
        ];
        assert!(enabled(2, "crate1::mod1", dirs.iter()));
        assert!(enabled(3, "crate2::mod2", dirs.iter()));
    }

    #[test]
    fn zero_level() {
        let dirs = [
            LogDirective { name: None, level: 3 },
            LogDirective { name: Some("crate1::mod1".to_string()), level: 0 }
        ];
        assert!(!enabled(1, "crate1::mod1", dirs.iter()));
        assert!(enabled(3, "crate2::mod2", dirs.iter()));
    }
}