Redesign the logging subsystem

[brson]

It is quite old and primitive at this stage, being mostly implemented in the runtime. With our new-found Rustic powers we should be able to come up with a more robust design.

Sub-bugs to handle along the way:

• RUST_LOG=::help should be sorted #8949 RUST_LOG=::help should be sorted
• Remove the longest-match logic in module-name matching for logging #6032 path prefix / full name RUST_LOG specs
• Trace task names in logging macros #2672 trace task names when logging
• multiple logging sinks #7805 multiple logging sinks
• Make logging work with new runtime code #5021 integration with new runtime code
• Monomorphised log statements have the wrong path in the crate_map #3046 monomorphized fns get wrong logging name
• Warn when RUST_LOG contains a name that isn't a valid path #2038 warn on nonmatching RUST_LOG
• Symbolic log levels, not just numbers #6031 symbolic log levels
• crate name in log map is taken from name of output binary, not the crate name #3346 wrong name for logging (uses binary, not crate name)
• logging functions handle unicode poorly #2154 unicode logging
• RUST_LOG=error should turn on error-level logging for all modules #6033 turning on everything with RUST_LOG=error
• rustc out of stack when RUST_LOG=rustc #5958 and RUST_LOG setting causes huge memory leak when building rustc #6558 OOM when running rustc with RUST_LOG on
• Custom polymorphic logging #2366 custom polymorphic logging

[nikomatsakis]

Note related request #4397

[catamorphism]

Note related request #3309

[emberian]

Hitting for triage

[emberian]

A log_push! and log_pop! would be pretty cool, like what q3 has (https://github.com/Jeaye/q3/blob/master/src/util/log_macros.rs). It lets you group a bunch of logs, claiming ownership of them.

[alexcrichton]

Nominating to de-nominate this issue, it's becoming less clear how to make progress on this issue as the sub-bugs are getting closed (just a few left after a branch of mine lands). I'll be nominating sub-bugs which I think should be nominated as well.

[catamorphism]

De-nominating since it's mostly done.

[nikomatsakis]

I feel like a big goal of this work was the ability for other people to make use of the logging system for something more than debug printfs. At first I was writing a comment saying how we hadn't even started on this design work as far as I could tell, but thinking more about it I decided that since designing a "one size fits all" logging system is quite the challenge, perhaps all we should really offer is some way to check whether logging for the current module is enabled at a given logging level. People can then build their own macros that do the equivalent of

if logging_enabled!(ERROR) { /* do whatever */ }

probably this hinges on some sort of macro so that we can have the macro be "enabled for the current module". As a bonus, this would probably permit us to write log statements that are enabled/disabled by the status of another module, which I've wanted on occasion.

[nikomatsakis]

Does the previous make sense? If so I'll open another bug. Either way, not a 1.0 issue.

[alexcrichton]

Despite the sub-tasks of this bug mostly being done, it seems that the general feeling is that "logging needs work", but at least to me it's unclear what work needs to get done (or what the general vision is for a futuristic logging system). This may be the appropriate place for such a description (it would pretty much replace the current one), but a new bug would also be fine.

As mentioned on IRC though, we do have a __log_level() language item which returns the logging level for whatever module it was invoked inside. This should probably be put behind a macro and then we wouldn't need to reserve the __log_level identifier, and it should also probably be more accessible in the sense of being more well defined than just returning a u32

[seanmonstar]

Is it too late to consider logging similar to Python's standard logging module? It provides a high degree of configuration with levels, filters, handlers (File, Stdout, Syslog, etc), and an hierarchical logging system.

I've done this once in nodejs, and would take this up as well if it seems like a good idea.

[emberian]

It's not too late at all. I feel like the current logging is very nice, if
not very flexible.

On Wed, Jan 22, 2014 at 1:06 AM, Sean McArthur [email protected]:

Is it too late to consider logging similar to Python's standard logging
modulehttp://docs.python.org/2/howto/logging.html#advanced-logging-tutorial?
It provides a high degree of configuration with levels, filters, handlers
(File, Stdout, Syslog, etc), and an hierarchical logging system.

I've done this once in nodejs http://seanmonstar.github.io/intel/, and
would take this up as well if it seems like a good idea.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/3309#issuecomment-32995913
.

[emberian]

@alexcrichton is there a nice way to access the crate map from non-libstd?
I feel like that'd be a nice and easy way to experiment with logging
outside of libstd.

On Wed, Jan 22, 2014 at 2:02 AM, Corey Richardson [email protected] wrote:

It's not too late at all. I feel like the current logging is very nice, if
not very flexible.

On Wed, Jan 22, 2014 at 1:06 AM, Sean McArthur [email protected]:

Is it too late to consider logging similar to Python's standard logging
modulehttp://docs.python.org/2/howto/logging.html#advanced-logging-tutorial?
It provides a high degree of configuration with levels, filters, handlers
(File, Stdout, Syslog, etc), and an hierarchical logging system.

I've done this once in nodejs http://seanmonstar.github.io/intel/, and
would take this up as well if it seems like a good idea.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/3309#issuecomment-32995913
.

[alexcrichton]

The format of the crate map is defined in libstd, and I wouldn't recommend interfacing with it from non-rust code. It can be inspected through std::rt::crate_map.

[seanmonstar]

I like the logging macros, they allow for library authors to easily use
logging. I would personally keep those, and introduce multiple handlers to
allow for multiple sinks, formatters, and a configure_logging! macro.

Should I start with an RFC, or just send a pull request?
On Jan 21, 2014 11:27 PM, "Alex Crichton" [email protected] wrote:

The format of the crate map is defined in libstd, and I wouldn't recommend
interfacing with it from non-rust code. It can be inspected through
std::rt::crate_map.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/3309#issuecomment-32998907
.

[alexcrichton]

If you've got some code ready, feel free to send it in, but you may want to ask around for opinions on what sort of features are desired by such a library.

We do have the ability to change the sink of logging macros, but it sounds like you're looking for something a little more involved than that?

[seanmonstar]

I'm looking for something like Python's logging: easy to log things, since it's built-in, all libraries can agree on a logging framework, because it's also extensible so that any app developers can chose exaclty what logs they see and where they go to.

Here's an example in Python:

import logging
logging.configure({
  'handlers': {
    'file': {
      'class': 'logging.FileHandler',
      'file': '/var/log/myapp.log'
    },
    'email': {
      'class': 'logging.EmailHandler',
      'level': 'ERROR',
      // from, to, etc
    }
  },
  'loggers': {
    'myapp': {
      'level': 'INFO',
      'handlers': ['file', 'email']
    },
    'mysql2': {
      'level': 'ERROR',
      'handlers': ['file']
    }
  }
})

As an app developer, I can say I want info or greater to go to my log file, and error or greater to email me, and from the mysql2 library, I only care about error level logs, and they go in my log file.

For Rust, I'd say keep the macros:

// mysql2.rs
debug!("QUERY {}", query);

And in my app, I could do something like this:

// myapp.rs
logging!(
  handlers: {
    stdout: std::logging::handlers::Stdout::new(),
    logly: myapp::logging::Logly::new()
  }
  loggers: {
    myapp: {},
    mysql2: {}
  }
);

[alexcrichton]

It sounds like this is all possible to do today. The Logger trait allows you to look at the logging level, and then you can do whatever you like with the message itself.

It doesn't sound likes it's easy to do that, though! I would err more on the side of wrapper structs that implement Logger that implement the functionality you're describing. For example you could have a logger which consumes other loggers to direct various messages to each one. This is all only done on a task-basis (not on a global basis), though.

[seanmonstar]

Pieces missing are a timestamp on the log record, though I suppose a wrapping logger could insert one, and the name of where the message came from. Such that you get messages in the log file like so:

[2014-01-22 10:14:11] mysql2::query::DEBUG -> QUERY Query{ someProps }
[2014-01-22 10:14:13] myapp::db::INFO -> insert Stuff{} success!

[alexcrichton]

Sadly right now we don't have a fantastic time abstraction in libstd, but you can certainly implement something like this with libextra's time module plus an implementation of the Logger trait (although we could certainly make this logging much easier to create)

[flaper87]

cc @flaper87

[alexcrichton]

With the new regex crate, the environment variable could now possibly take a regular expression as well.

[huonw]

It's seems like it would be somewhat harder to define the precedence of the RUST_LOG variables. E.g. I believe currently a::b=error,a=warn will emit warn!s for everything in a except for things also inside a::b. With regular expressions there's not such a clear ordering based on the module hierarchy.

I guess we could just do it based on the order in which the directives are specified (unfortunately, it seems like using regexes might also be harder to get to be efficient... but maybe this doesn't matter so much).

[w3ln4]

Hello folks,

I'm trying to figure out the Rust logging system and got some questions and
notes which seems to be not covered by the documentation. I am also new to the
Rust itself so many things may not be understandable for me. I've tried to look
for some design or plans for logging system but it looks like this issue is
the only such place. One more note: I am working on a Linux version of Rust. I
didn't test it on other platforms.

I. Outputing.

• Using stderr.

By default, logging is performed to the stderr output of the process. It's a
quite nice and intuitive feature but the way it works is a little problematic.
It makes you think that you are able to redirect all the logging simply by
redirecting stderr output which unfortunately does not work! Calling
set_stderr will only redirect fail! messages but no log! messages.

Moreover, even if I spawn a task using TaskBuilder with custom stderr set upon
creation, the logging would not be redirected to it which is even more
counterintuitive.

• Using set_logger

Hence, the only way to redirect the logging is using set_logger function. The
problem is that if I would like to redirect all logs to a custom writer I will
have to call it for every created task. It would be useful then if I could set
logger using TaskBuilder method logger() if one were added.

• Connecting above

Personally, I like the idea that logging is connected to stderr. It seems to
me that stderr is wastefully only used for fail! messages for now. But problems
from point 1 makes it currently unusable. It would require though changing the
Logger logic to something like LogFormatter and the user of set_log_formatter
would only be responsible for setting custom formating of the log messages,
not outputing it.

How about outputing logs to multiple sinks? I thought about possibility to set
stderr to MultiWriter but I was not able to get it running even if all
underlying Writers were sendable. Is it possible to use it in such a way?

II. Miscs.

• Feature hiding

Is logging system always going to be hiden inside phase plugin directive? Or
will it be incorporated to the std lib sometime? Typing these lines for every
module seems to be a bit cumbersome.

• static LogLocations

I saw that log! macro is creating a static LogLocation struct. Does it mean
that for every logging macro such a structure is created in global data
section or is it created only once? Wouldn't it be better to simply pass line,
file, module_path parameters to log function?

I think that's all that comes to my mind for now. Any answers will be highly
appreciated.

[seanmonstar]

@w3ln4

1. Currently, to change the sink for logging, you will need to call set_logger with your own Logger. This custom logger could filter records and send them to different sinks depending on your own criteria. However, you would need to call set_logger in every task, which is poop. The logging crate would need to store the logger in something shared between tasks, instead of task local storage.
2. Anything in #![features()] are currently feature-gated. The goal is for them to become stable and no longer behind a gate, but pre-1.0, you have to opt-in to use them, agreeing that the feature could change completely.
3. The static loglocations actually reduce the amount of code generated. I don't know the specifics, but @alexcrichton was the one who suggested it.

[alexcrichton]

Closing, liblog has moved out of the distribution and almost all linked bugs here are fixed. Redesigns (like rust-lang/log#3) can easily happen out of tree, and discussion should probably continue on the liblog issue tracker.