rust/src/liblog/lib.rs

// Copyright 2015 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

This module is used by the compiler when emitting output for the logging family
of macros. The methods of this module shouldn't necessarily be used directly,
but rather through the logging macros defined.

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 std::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 std::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:

```notrust
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 std::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:

```notrust
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
```

## 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.

*/

#[crate_id = "log#0.10-pre"];
#[license = "MIT/ASL2"];
#[crate_type = "rlib"];
#[crate_type = "dylib"];
#[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://static.rust-lang.org/doc/master")];

#[feature(macro_rules)];
#[deny(missing_doc)];

extern crate sync;

use std::cast;
use std::fmt;
use std::io::LineBufferedWriter;
use std::io;
use std::local_data;
use std::os;
use std::rt;
use std::vec;
use std::vec_ng::Vec;

use sync::one::{Once, ONCE_INIT};

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 static MAX_LOG_LEVEL: u32 = 255;

/// The default logging level of a crate if no other is specified.
static 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: *Vec<directive::LogDirective> =
    0 as *Vec<directive::LogDirective>;

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

local_data_key!(local_logger: ~Logger)

/// 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 `args` structure. The level is
    /// provided in case you want to do things like color the message, etc.
    fn log(&mut self, level: u32, args: &fmt::Arguments);
}

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

impl Logger for DefaultLogger {
    // by default, just ignore the level
    fn log(&mut self, _level: u32, args: &fmt::Arguments) {
        match fmt::writeln(&mut self.handle, args) {
            Err(e) => fail!("failed to log: {}", e),
            Ok(()) => {}
        }
    }
}

impl Drop for DefaultLogger {
    fn drop(&mut self) {
        // FIXME(#12628): is failure the right thing to do?
        match self.handle.flush() {
            Err(e) => fail!("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.
pub fn log(level: u32, args: &fmt::Arguments) {
    // 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_data::pop(local_logger).unwrap_or_else(|| {
        ~DefaultLogger { handle: io::stderr() } as ~Logger
    });
    logger.log(level, args);
    local_data::set(local_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: ~Logger) -> Option<~Logger> {
    let prev = local_data::pop(local_logger);
    local_data::set(local_logger, logger);
    return prev;
}

/// 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 mut INIT: Once = ONCE_INIT;
    unsafe { INIT.doit(init); }

    // It's possible for many threads are in this function, only one of them
    // will peform 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: vec::Items<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) => {},
            Some(..) | None => {
                return level <= directive.level
            }
        }
    }
    level <= DEFAULT_LOG_LEVEL
}

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

    // 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!(DIRECTIVES.is_null());
        DIRECTIVES = cast::transmute(~directives);

        // Schedule the cleanup for this global for when the runtime exits.
        rt::at_exit(proc() {
            assert!(!DIRECTIVES.is_null());
            let _directives: ~Vec<directive::LogDirective> =
                cast::transmute(DIRECTIVES);
            DIRECTIVES = 0 as *Vec<directive::LogDirective>;
        });
    }
}

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

    #[test]
    fn match_full_path() {
        let dirs = [LogDirective { name: Some(~"crate2"), level: 3 },
                    LogDirective { name: Some(~"crate1::mod1"), 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"), level: 3 },
                    LogDirective { name: Some(~"crate1::mod1"), level: 2 }];
        assert!(!enabled(2, "crate3", dirs.iter()));
    }

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

    #[test]
    fn match_beginning_longest_match() {
        let dirs = [LogDirective { name: Some(~"crate2"), level: 3 },
                    LogDirective { name: Some(~"crate2::mod"), level: 4 },
                    LogDirective { name: Some(~"crate1::mod1"), 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"), 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"), level: 0 }];
        assert!(!enabled(1, "crate1::mod1", dirs.iter()));
        assert!(enabled(3, "crate2::mod2", dirs.iter()));
    }
}