RFC: Make RUST_LOG={error,warning,debug,all} work

[pcwalton]

The RUST_LOG syntax is very mysterious right now. I propose a syntax that looks like this:

• RUST_LOG=all — logs everything.
• RUST_LOG=error — logs errors.
• RUST_LOG=e — same as above.
• RUST_LOG=warning — logs errors and warnings.
• RUST_LOG=warning,typeck — logs errors and warnings in modules nested somewhere within a module named "typeck" (including deeper modules).
• RUST_LOG=all,typeck,trans — logs all messages coming from a module named "typeck" and all messages coming from a module named "trans"
• RUST_LOG=debug,rustc::middle::typeck — logs errors and warnings in modules nested somewhere within a module named "typeck" inside a module named "middle" inside a module named "rustc"
• RUST_LOG=help — displays a help message in the runtime, then exits.

IMHO this would be easy to use.

Basically the log statement would pass a list of module names to the runtime, and the logging function would do a string comparison on each path component to determine which to print.

[catamorphism]

I support this proposal. We could still support the old syntax too, for those who like conciseness; I guess there's no harm in it.

[graydon]

Your suggestion is a bit ambiguous. Let's try to be specific. I agree it's cumbersome at present. The existing scheme is:

RUST_LOG=<module_prefix>[=<log_level>],<module_prefix>[=<log_level>],...`

There are ways we could improve this:

• Symbolic log levels, not just numbers
• Removing the longest-match logic in module-name matching (I don't actually understand what it's doing presently)
• Interpreting an (ambiguous) bareword that matches a symbolic log level name as the log level applied to every module, rather than a module name set to the default log level

You pretty much never want all. It logs a lot. Really a lot. Every malloc, every task switch, every character peeked-at while parsing..

[pcwalton]

So the proposal is to use the following pseudo-BNF to match the contents of RUST_LOG:

LogSpec ::== 'help' | LogLevel (',' Module)*
LogLevel ::== Error | Warning | Info | Debug
Error ::== 'e' | 'er' | 'err' | 'erro' | 'error' | 'errors'
Warning ::== 'w' | 'wa' | 'war' | 'warn' | 'warni' | 'warnin' | 'warning' | 'warnings'
Info ::== 'i' | 'in' | 'inf' | 'info'
Debug ::== 'd' | 'de' | 'deb' | 'debu' | 'debug'
Module ::== AbsoluteModule | ModuleFragment
AbsoluteModule ::== ('::' Identifier)+
ModuleFragment ::== Identifier ('::' Identifier)*
Identifier ::== [a-zA-Z_][a-zA-Z0-9_]*

The semantics are as follows:

• Specifying a log level alone turns on log messages for that level and up (so e.g. warn turns on errors and warnings), for all modules.
• Specifying a module name turns on log messages for that module only.
• Specifying multiple modules turns on log messages for those modules only.
• An absolute module (denoted by leading ::) specifies an absolute module path from the top of the crate.
• A module fragment specifies any module whose absolute top-level path ends in that string. For example, a::b::c would match modules ::d::e::a::b::c or ::a::b::c, but not ::a::b::c::d. The first module in the path must match the name of the outermost module exactly, so a::b::c does not match abracadabra::b::c.

[catamorphism]

Shall we interpret silence as consensus in favor of @pcwalton 's last comment here? (I support it.)

[danluu]

This seems to partially work. @astrieanna and I were trying to figure out how to fix this, and we got bogged down in the parsing code, trying to figure out how RUST_LOG affects the behavior of __log(lvl, msg).

The manual indicates that numbers should be used to indicate the logging level, but that feature appears to have been removed (or perhaps it's incomplete):

debug.rs

fn main() {
    error!("error")
    warn!("warn")
    info!("info")
    debug!("debug")
}

$ export RUST_LOG=0
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=1
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=2
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=3
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=4
$ ./debug
rust: ~"\"error\""

We also tried to format described in this issue, which partially works.

$ export RUST_LOG=all
$ ./debug
rust: ~"\"error\""                                                                                                                                                   
$ export RUST_LOG=error
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=warning
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=info
$ ./debug
rust: ~"\"error\""
$ export RUST_LOG=debug
$ ./debug
rust: ~"\"error\""
rust: ~"\"warn\""
rust: ~"\"info\""
rust: ~"\"debug\""

The help command doesn't seem to be implemented. There's a ::help and ?, in rust_log.cpp but that appears to be something completely different?

In rust_log.h, the different log levels are defined, and there are #define macros that use log_debug and log_error, but not log_warn and log_info.

It seems like we could fix this by defining the appropriate #define macros for log_warn and log_info, but we couldn't figure out if that's the right thing to do, because we don't undertand how they're being called (are LOG, DLOG, etc. only used for internal errors, or if __log somehow calls one of those macros). Also, we couldn't find where RUST_LOG=debug gets translated into 4, so we aren't sure if the other logging levels are actually translated to anything.

If you understand the code associated with this issue, would you mind pointing us to the right things to look at, so we can take a crack at fixing it?

[steveklabnik]

I wrote that manual entry like a week ago, shortly after the 0.6 release. So it must have been a really recent changed :(

[lkuper]

@danluu, @astrieanna: RUST_LOG is kind of arcane. From https://github.com/mozilla/rust/wiki/Doc-usage-FAQ :

RUST_LOG takes a 'logging spec' that consists of a comma-separated list of paths, where a path consists of the crate name and sequence of module names, each separated by double-colons. For standalone .rs files the crate is implicitly named after the source file

For your debug.rs example, the program implicitly consists of a single crate, which is called debug, so the path you use in the logging spec is simply debug. I think this led to some confusion because in addition to being the crate name, debug is also the name of one of the logging levels, so you used it by accident up above!

landin:~ lkuper$ rustc debug.rs
warning: no debug symbols in executable (-arch x86_64)
landin:~ lkuper$ export RUST_LOG=debug
landin:~ lkuper$ ./debug
rust: ~"error"
rust: ~"warn"
rust: ~"info"
rust: ~"debug"
landin:~ lkuper$

The numbers, which indicate log levels, are optional, and you append them to the path with an equals sign (=). The default log level is 4, which means "log everything", but you can narrow it down:

landin:~ lkuper$ export RUST_LOG=debug=4; ./debug
rust: ~"error"
rust: ~"warn"
rust: ~"info"
rust: ~"debug"
landin:~ lkuper$ export RUST_LOG=debug=3; ./debug
rust: ~"error"
rust: ~"warn"
rust: ~"info"
landin:~ lkuper$ export RUST_LOG=debug=2; ./debug
rust: ~"error"
rust: ~"warn"
landin:~ lkuper$ export RUST_LOG=debug=1; ./debug
rust: ~"error"
landin:~ lkuper$ export RUST_LOG=debug=0; ./debug
landin:~ lkuper$

It's admittedly kind of a pain to have to specify the crate name in the log spec, even when it's a single .rs file with no modules and there's only one path that could possibly be the one you mean. RUST_LOG is optimized for the case of debugging large Rust executables (like rustc itself) that are built out of many crates with lots and lots of modules, where you want to pick and choose what gets logged with laser-like precision.

Take this file, for instance:

// foo.rs

mod a {

    pub fn a() {
        error!("error from module a")
        warn!("warn from module a")
        info!("info from module a")
        debug!("debug from module a")
    }
}

mod b {

    pub fn b() {
       error!("error from module b")
       warn!("warn from module b")
       info!("info from module b")
       debug!("debug from module b")
    }
}

fn main() {
   a::a();
   b::b();
}

If I want to log everything, I can:

landin:~ lkuper$ rustc foo.rs
warning: no debug symbols in executable (-arch x86_64)
landin:~ lkuper$ export RUST_LOG=foo; ./foo
rust: ~"error from module a"
rust: ~"warn from module a"
rust: ~"info from module a"
rust: ~"debug from module a"
rust: ~"error from module b"
rust: ~"warn from module b"
rust: ~"info from module b"
rust: ~"debug from module b"
landin:~ lkuper$

But maybe I just want to log module a:

landin:~ lkuper$ export RUST_LOG=foo::a; ./foo
rust: ~"error from module a"
rust: ~"warn from module a"
rust: ~"info from module a"
rust: ~"debug from module a"
rust: ~"error from module b"
landin:~ lkuper$

Here we still get the error from module b because errors get logged by default unless we turn them off by setting module b's log level to 0:

landin:~ lkuper$ export RUST_LOG=foo::a,foo::b=0; ./foo
rust: ~"error from module a"
rust: ~"warn from module a"
rust: ~"info from module a"
rust: ~"debug from module a"
landin:~ lkuper$

So, @steveklabnik's manual entry looks OK to me, but perhaps it could stand to have some examples of logging specifications.

(The examples in this comment are with rustc 0.5.)

[lkuper]

Also, I think it would make sense to close this bug, and instead open separate bugs (if they don't already exist) for the suggestions in graydon's comment above.

[pcwalton]

Filed #6031, #6032, #6033 per @lkuper's suggestion.