Skip to content

A few logging improvements #9664

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Oct 9, 2013
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 9 additions & 3 deletions src/librustc/middle/trans/expr.rs
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,7 @@ use back::link;
use lib::llvm::{ValueRef, llvm, SetLinkage, False};
use lib;
use metadata::csearch;
use metadata::cstore;
use middle::trans::_match;
use middle::trans::adt;
use middle::trans::asm;
Expand Down Expand Up @@ -1797,9 +1798,14 @@ pub fn trans_log_level(bcx: @mut Block) -> DatumBlock {
let ccx = bcx.ccx();

let (modpath, modname) = {
let path = &mut bcx.fcx.path;
let mut modpath = ~[path_mod(ccx.sess.ident_of(ccx.link_meta.name))];
for e in path.iter() {
let srccrate = match ccx.external_srcs.find(&bcx.fcx.id) {
Some(&src) => {
cstore::get_crate_data(ccx.sess.cstore, src.crate).name
}
None => ccx.link_meta.name,
};
let mut modpath = ~[path_mod(ccx.sess.ident_of(srccrate))];
for e in bcx.fcx.path.iter() {
match *e {
path_mod(_) => { modpath.push(*e) }
_ => {}
Expand Down
3 changes: 0 additions & 3 deletions src/librustc/rustc.rs
Original file line number Diff line number Diff line change
Expand Up @@ -194,9 +194,6 @@ pub fn describe_debug_flags() {
}

pub fn run_compiler(args: &[~str], demitter: @diagnostic::Emitter) {
// Don't display log spew by default. Can override with RUST_LOG.
::std::logging::console_off();

let mut args = args.to_owned();
let binary = args.shift().to_managed();

Expand Down
115 changes: 88 additions & 27 deletions src/libstd/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -8,40 +8,101 @@
// option. This file may not be copied, modified, or distributed
// except according to those terms.

//! Logging
/*!

use fmt;
use option::*;
use os;
use rt;
use rt::logging::{Logger, StdErrLogger};
Logging

/// Turns on logging to stdout globally
pub fn console_on() {
rt::logging::console_on();
}
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.

/**
* Turns off logging to stdout globally
*
* Turns off the console unless the user has overridden the
* runtime environment's logging spec, e.g. by setting
* the RUST_LOG environment variable
*/
pub fn console_off() {
// If RUST_LOG is set then the console can't be turned off
if os::getenv("RUST_LOG").is_some() {
return;
}
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 4
* `info!(...)` - a macro hard-wired to the log level of 3
* `warn!(...)` - a macro hard-wired to the log level of 2
* `error!(...)` - a macro hard-wired to the log level of 1

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

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

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

rt::logging::console_off();
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::hashmap // turns on hello, and std's hashmap 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
if log_level <= my_module_log_level() {
::std::logging::log(log_level, format!(...));
}
```

#[allow(missing_doc)]
pub fn log(_level: u32, args: &fmt::Arguments) {
use rt::task::Task;
use rt::local::Local;
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.

## Useful Values

For convenience, if a value of `::help` is set for `RUST_LOG`, a program will
start, print out all modules registered for logging, and then exit.

*/

use fmt;
use option::*;
use rt::local::Local;
use rt::logging::{Logger, StdErrLogger};
use rt::task::Task;

/// 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) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can't we just remove the _level arg?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd rather not completely remove it. In theory we could do things like colorizing log message or something fun like that, but in general it seems like "this might be useful" for a future evolvement of a logging library, even if we're just not using it right now.

My main worry would be that this is a perfectly reasonable function to call directly (via some call chain with format_args! at the top), and it seems appropriate to take a level, and just unfortunate that we don't do anything with it just yet.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed with @alexcrichton here. Based on the way logging happens, it would be very weird not to have a level argument, It's also strange that it's not being used yet.

unsafe {
let optional_task: Option<*mut Task> = Local::try_unsafe_borrow();
match optional_task {
Expand Down
21 changes: 2 additions & 19 deletions src/libstd/rt/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@

use fmt;
use from_str::from_str;
use libc::{uintptr_t, exit};
use libc::exit;
use option::{Some, None, Option};
use rt;
use rt::util::dumb_println;
Expand Down Expand Up @@ -182,9 +182,7 @@ pub struct StdErrLogger;

impl Logger for StdErrLogger {
fn log(&mut self, args: &fmt::Arguments) {
if should_log_console() {
fmt::writeln(self as &mut rt::io::Writer, args);
}
fmt::writeln(self as &mut rt::io::Writer, args);
}
}

Expand Down Expand Up @@ -220,21 +218,6 @@ pub fn init() {
}
}

#[fixed_stack_segment] #[inline(never)]
pub fn console_on() { unsafe { rust_log_console_on() } }

#[fixed_stack_segment] #[inline(never)]
pub fn console_off() { unsafe { rust_log_console_off() } }

#[fixed_stack_segment] #[inline(never)]
fn should_log_console() -> bool { unsafe { rust_should_log_console() != 0 } }

extern {
fn rust_log_console_on();
fn rust_log_console_off();
fn rust_should_log_console() -> uintptr_t;
}

// Tests for parse_logging_spec()
#[test]
fn parse_logging_spec_valid() {
Expand Down
21 changes: 0 additions & 21 deletions src/rt/rust_builtin.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -326,27 +326,6 @@ rust_mktime(rust_tm* timeptr) {
return mktime(&t);
}

static lock_and_signal log_lock;
static bool log_to_console = true;

extern "C" CDECL void
rust_log_console_on() {
scoped_lock with(log_lock);
log_to_console = true;
}

extern "C" CDECL void
rust_log_console_off() {
scoped_lock with(log_lock);
log_to_console = false;
}

extern "C" CDECL uintptr_t
rust_should_log_console() {
scoped_lock with(log_lock);
return log_to_console;
}

extern "C" lock_and_signal*
rust_create_little_lock() {
return new lock_and_signal();
Expand Down
3 changes: 0 additions & 3 deletions src/rt/rustrt.def.in
Original file line number Diff line number Diff line change
Expand Up @@ -18,9 +18,6 @@ rust_get_stderr
rust_list_dir_val
rust_list_dir_wfd_size
rust_list_dir_wfd_fp_buf
rust_log_console_on
rust_log_console_off
rust_should_log_console
rust_unset_sigprocmask
rust_env_pairs
upcall_rust_personality
Expand Down
14 changes: 14 additions & 0 deletions src/test/auxiliary/logging_right_crate.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
// Copyright 2013 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.

pub fn foo<T>() {
fn death() -> int { fail2!() }
debug2!("{:?}", (||{ death() })());
}
30 changes: 30 additions & 0 deletions src/test/run-pass/logging-right-crate.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
// Copyright 2013 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.

// aux-build:logging_right_crate.rs
// xfail-fast
// exec-env:RUST_LOG=logging-right-crate=debug
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/-/_/g

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was actually intentional. Before these changes the program would actually fail because the wrong crate name was used as the top-level name. I suppose that I could make this run-fail, but all it would be doing is inverting the logic.

Right now I ask logging of this crate, and shouldn't get logging of the external crates, but the other way around I'd ask for logging of the external crate and make sure that logging of this crate didn't happen.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, ok. Probably worth a comment to this effect so that someone trying to work out what the test is doing in a year isn't entirely confused? ;)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Comment added below.


// This is a test for issue #3046 to make sure that when we monomorphize a
// function from one crate to another the right top-level logging name is
// preserved.
//
// It used to be the case that if logging were turned on for this crate, all
// monomorphized functions from other crates had logging turned on (their
// logging module names were all incorrect). This test ensures that this no
// longer happens by enabling logging for *this* crate and then invoking a
// function in an external crate which will fail when logging is enabled.

extern mod logging_right_crate;

fn main() {
// this function fails if logging is turned on
logging_right_crate::foo::<int>();
}