Transform liblog into a logging facade

[sfackler]

There are a couple of distinct kinds of programs, each of which has different needs from a logger:

• Short running programs like rustc need a simple logging framework that provides some reasonable level of configurable filtering when trying to debug a problem.
• Embedded programs or kernels may not have a stderr at all. They may, however, have the ability to log information through a serial port or network interface.
• Long running programs like servers have more advanced logging needs than the current crate provides. In this case, dynamic reconfiguration of logging filters is very helpful, as is the ability to have multiple "sinks" that can output to the console, rolling files, the syslog, over the network, etc.
• Programs that don't care about logging shouldn't be spammed with unwanted information from libraries that they use.

The current liblog implementation covers the first and last use cases, but misses the middle two.

There are two competing concerns here: we want a single logging interface that libraries can use - it would be crazy to expect someone to provide different versions of a single crate that only differ by their choice of logging framework! But at the same time, we want the libraries to be usable in all of the contexts mentioned above, with their logging intact.

One solution is to turn liblog into a logging "facade". It provides the infrastructure to allow libraries to send log messages, while allowing the downstream application to chose the actual logging framework that will process the log messages. One example is the slf4j library for Java, which allows libraries to log in a way that will work with any of the many logging frameworks available in Java: java.util.logging, log4j, Logback, etc.

I have a prototype conversion of liblog to a facade in the log-ng project. It consists of three crates:

• log_ng - the core facade
• basic - a port of liblog's current RUST_LOG based log implementation
• log4r - a prototype of a more complex logger in the vein of log4j and Logback.

Documentation is available here: http://sfackler.github.io/log-ng/doc/log_ng/

Changes from liblog

While converting liblog, I did make some changes to the current functionality:

• The log levels are now an enum instead of a u32, consisting of Off, Error, Warn, Info, Debug, and Trace. Note that Trace is new. I don't really see the use in having 255 distinct levels, and it simplifies parsing and pretty-printing of the level if we can restrict the level to an enum.
• The logging macros don't call enabled before calling log. It turned out when I was experimenting with logger implementations that log can pretty trivially perform the filtering itself. If argument computation is expensive, the log_enabled! macro is still available, which will call through to enabled.
• There is now a single global logger instead of thread-local loggers. The current liblog implementation does provide the ability to set the logger, but since it's task local, it's impossible to make sure the right logger is installed in each thread - think of threads started by TaskPool for example. Having thread-local loggers also results in a log of duplicated data and computation. The RUST_LOG environment variable has to be reparsed every time a program logs on a new thread, for example. In addition, it's not totally clear to me that anyone actually wants to have different loggers on different threads. Even if one does, it's pretty easy to make a thread local logger implementation for the logging facade.
• The ndebug cfg is checked only in debug! and trace!, not in log! as well. I'm not sure what the right thing to do is here, but it seems like completely forbidding the use of the debug and trace levels with optimizations enabled is over-aggressive, especially since the global maximum log level check makes them pretty cheap when those levels are disabled. We may want to have debug! and trace! always enabled, and have separate debug build only versions.

Interesting notes/design decisions

• The logger may only be initialized once, and isn't torn down when a program exits. It's possible to support logger replacement and teardown with atexit but it would require storing the logger in an Arc and adding a couple extra atomic reads and writes every time a message is logged. I'm not sure what the right answer is here. I don't really think people will want to swap their loggers out dynamically, but cleanup at exit seems like a nice thing to do to avoid spamming Valgrind.
• Log messages generated when the logger is not initialized are ignored. Some logging facades like slf4j fall back to a simple logging implementation that dumps messages at the higher levels to the console. We could do this, but I'm a bit hesitant to do something that'll clutter the console for programs that don't want logging information as well as slow them down.
• A logger has to be manually installed. slf4j can use some reflective classpath scanning magic to automatically set itself up to use common logging frameworks if they're present on the classpath, but we don't really have that ability. We may be able to do some dark magick with weak linkage, but I think that explicit is better than implicit here.

Remaining problems/blockers

• Since the logger has to be manually initialized, it becomes very hard to use when running tests. You could make a Once and use that to initialize the logger in every test, but that adds a huge amount of pain to adding new tests. I think the best solution here is to augment rust's test support to add something like Go's TestMain function or junit's @BeforeClass annotation to allow for global setup before any tests run. This is useful in other contexts as well for other global resource setup.

Thoughts?

[alexcrichton]

This seems like a pretty great idea! I don't personally have many strong opinions about logging or what direction this library should go in, and I also don't mind deprecating this library as-is (just going into maintenance mode) to make room for another.

Some thoughts:

The log levels are now an enum instead of a u32

This seems like a good idea.

The logging macros don't call enabled before calling log

Some use cases of logging may hurt because of this, but I'd be willing to believe that they're fairly few and somewhat niche.

There is now a single global logger instead of thread-local loggers

This also seems like a good idea.

In addition, it's not totally clear to me that anyone actually wants to have different loggers on different threads

The one use case I know of for this is a unit testing framework where you want to capture each test's output individually. As you mentioned though you can build this on top of a global framework so it's probably not that bad to lose.

The logger may only be initialized once, and isn't torn down when a program exits

The lack of teardown seems somewhat worrying to me, but the one-time initialization is probably fine.

The strategy I'm going to try to take elsewhere is that once atexit starts running, it's considered a task panic to continue accessing logging. This means that you'll need synchronization around it, but it probably all comes out in the wash.

A logger has to be manually installed

This seems somewhat reasonable. If I've invested time and effort into using a logging infrastructure I'm probably willing to set it up to get it running.

[sfackler]

The lack of teardown seems somewhat worrying to me, but the one-time initialization is probably fine.

The strategy I'm going to try to take elsewhere is that once atexit starts running, it's considered a task panic to continue accessing logging. This means that you'll need synchronization around it, but it probably all comes out in the wash.

Yeah, thinking about it a bit more, you'd definitely want teardown to flush buffers at the very least. I'm not a huge fan of having post-atexit calls panic. Seems like they should just be noops to avoid weird transient failures that are hard to reproduce.

[sfackler]

Adding at_exit cleanup wasn't that bad, though the implementation involves some "interesting" uses of atomics: https://github.com/sfackler/log-ng/commit/0bc99ed5b0e2b0f417257921cda78c5ef3612f7b.

I also don't mind deprecating this library as-is (just going into maintenance mode) to make room for another.

I'd prefer to keep the implementation in the log crate since it'd be a bummer to burn a good name so quickly. That could mean keeping it in this repo or just transferring ownership on crates.io.

[alexcrichton]

That's a good point, I wouldn't mind moving this crate more towards a different design, may want to discuss with a few others though :)

[Ericson2314]

The logging macros don't call enabled before calling log

I would like it if in addition to the dynamic logging level, there was a static logging level -- a compile time choice of what types of logging are even available. This should recover all the niche uses of the old system and impose no burdens the common case.

If cfg! wasn't used in the logging macros (for the static level) but #[cfg(.,.)] instead, the logging facade could be unconditionally #[phase(plugin)] externd, and conditionally be #[phase(link)] externd to completely go away at the most restrictive static logging level.

[sfackler]

A static logging level seems like a great idea. I've been worrying a bit about debug! and trace! being tied to ndebug, but a separate cfg seems like a better way of handling that.

#[cfg(...)] can't be attached to expressions right now, which would prohibit its use here. cfg! should be fine, as if cfg!(foo) { stuff } ends up as if false { stuff } which is trivially optimized away. In fact, I believe the removal of if false {..} blocks is one of the very few optimizations performed by rustc itself instead of llvm.

[sfackler]

@Ericson2314 is this something like what you had in mind? https://github.com/sfackler/log-ng/commit/f40621c311ab82af8ded28b79566ccdcec427d99

[Ericson2314]

Glad you like it!

That's most of it. My thing about cfg! vs #[cfg(.,.)] is that in the case where logging is effectively statically disabled, log probably won't get linked in the end, but could anyways. By aggressively using #[cfg(...)] it might be possible to guarantee log goes away entirely -- and that might be a useful invariant for people distributing proprietary binaries or something.

What do we use ndebug for currently? If just for debug_assert and friends, might we remove it altogether now that log is becoming is so much more flexible?

[sfackler]

I believe debug_assert is the only thing built into the standard distribution that uses ndebug.

We could potentially do something like this, though it's pretty bizzaro looking:

macro_rules! debug {
    ($($arg:tt)*) => (
        match () {
            #[cfg(not(any(log_level = "off",
                          log_level = "error",
                          log_level = "warn",
                          log_level = "info")))]
            () => log!(::log_ng::LogLevel::Debug, $($arg)*),
            #[cfg(any(log_level = "off",
                      log_level = "error",
                      log_level = "warn",
                      log_level = "info")))]
            () => (),
        }
    )
}

[Ericson2314]

That's a great trick!

I'm now firmly in scrapping debug_assert. If debug_assert is /used/ by the standard library, not merely defined in it. liblog can be used, and just compiled out for release.

[sfackler]

Keep in mind that debug_assert! has nothing to do with logging. It's just like assert! except that it turns into a noop when compiled with ndebug.

[Ericson2314]

Well debugging and logging are related, broadly. And having one library to manage all optional sanity checks seems convenient.

[Ericson2314]

Hmm, I'm trying

#[macro_use] #[no_link]
extern crate log_ng;

#[cfg(any(log_level = "off",
          log_level = "error",
          log_level = "warn",
          log_level = "info",
          log_level = "debug"))]
extern crate log_ng;

But it doesn't seem to be working. Perhaps those cfgs are being resolved in log_ng itself?

[sfackler]

Are you passing one of those to rustc?

[Ericson2314]

no, but the macros are asking for things in log_ng.

[sfackler]

The macros expand inline into crates that use them, and that's where the cfg takes effect.

[Ericson2314]

Oh no. Is there anyway to delay that?