• For #149
• Includes #281 as an alternative design

Rendered

Reference implementation

Sample API docs

Hi! So we've been working through some designs in #149 on how structured logging could be supported in log. I've since gone away and tried to capture the results of that discussion and my experiments over the year into a concrete proposal that we can refine further. It looks pretty long, but a fair chunk of that is blocks of source.

I don't necessarily expect us to merge this PR even once we're happy with it, it's really just an effort to get more directed feedback on a significant API using a process we're familiar with in the Rust community.

cc @sfackler @dpc (who I know has limited capacity) @Thomasdezeeuw

Open questions:

• [x] macro syntax

Add support to log for inline expression and value logging, as a superset of the dbg! macro recently added to rust std.

Rendered

Implementation PR: #316

As the log crate is a very core part of the Rust ecosystem, it would be wonderful if by the end of 2020 it could join the set of illustrious crates that have begun to follow strong semver by releasing a 1.0 version.

Is it time we make a roadmap to that goal? Are there things blocking that from happening?

Currently, log levels are represented by a LogLevel enum:

pub enum LogLevel {
    Error,
    Warn,
    Info,
    Debug,
    Trace,
}

In my experience, five log levels is enough for most use cases. However, I don't see a reason why log should limit the user to this finite set. Consider adding a custom-verbosity variant that includes an integer specifying the log level:

pub enum LogLevel {
    Error,
    Warn,
    Info,
    Debug,
    Trace,
    CustomVerbosity(u8), // bikeshed away on the name :)
}

Apologies if I missed an existing issue or conversation around this!

Fixes #116.

Create builders to support the construction of Metadata, Record, and Level. I decided to take mut self as the parameter for each builder method because it allows:

let record = RecordBuilder::new().args(...).metadata(...).build()

Whereas taking &mut self leads to the temporary object created by RecordBuilder::new() being dropped before build().

Not done yet--still need to add examples/docs. Please review everything else!

fixes #79

This is a feature I'll definitely use in serde-xml, and probably implement it for json, too. Basically anything that processes tree-structures benefits enormously from it.

example run with miri:

Interpreting: factorial_recursive
 TRACE:miri::interpreter: // bb0
 TRACE:miri::interpreter: return = factorial_recursive::fact(const 10i64) -> bb1
  TRACE:miri::interpreter: // bb0
  TRACE:miri::interpreter: var0 = arg0
  TRACE:miri::interpreter: tmp1 = var0
  TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
  TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
  TRACE:miri::interpreter: // bb3
  TRACE:miri::interpreter: tmp2 = var0
  TRACE:miri::interpreter: tmp5 = var0
  TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
  TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
   TRACE:miri::interpreter: // bb0
   TRACE:miri::interpreter: var0 = arg0
   TRACE:miri::interpreter: tmp1 = var0
   TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
   TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
   TRACE:miri::interpreter: // bb3
   TRACE:miri::interpreter: tmp2 = var0
   TRACE:miri::interpreter: tmp5 = var0
   TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
   TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    TRACE:miri::interpreter: // bb0
    TRACE:miri::interpreter: var0 = arg0
    TRACE:miri::interpreter: tmp1 = var0
    TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    TRACE:miri::interpreter: // bb3
    TRACE:miri::interpreter: tmp2 = var0
    TRACE:miri::interpreter: tmp5 = var0
    TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |TRACE:miri::interpreter: // bb0
    |TRACE:miri::interpreter: var0 = arg0
    |TRACE:miri::interpreter: tmp1 = var0
    |TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |TRACE:miri::interpreter: // bb3
    |TRACE:miri::interpreter: tmp2 = var0
    |TRACE:miri::interpreter: tmp5 = var0
    |TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    | TRACE:miri::interpreter: // bb0
    | TRACE:miri::interpreter: var0 = arg0
    | TRACE:miri::interpreter: tmp1 = var0
    | TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    | TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    | TRACE:miri::interpreter: // bb3
    | TRACE:miri::interpreter: tmp2 = var0
    | TRACE:miri::interpreter: tmp5 = var0
    | TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    | TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |  TRACE:miri::interpreter: // bb0
    |  TRACE:miri::interpreter: var0 = arg0
    |  TRACE:miri::interpreter: tmp1 = var0
    |  TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |  TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |  TRACE:miri::interpreter: // bb3
    |  TRACE:miri::interpreter: tmp2 = var0
    |  TRACE:miri::interpreter: tmp5 = var0
    |  TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |  TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |   TRACE:miri::interpreter: // bb0
    |   TRACE:miri::interpreter: var0 = arg0
    |   TRACE:miri::interpreter: tmp1 = var0
    |   TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |   TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |   TRACE:miri::interpreter: // bb3
    |   TRACE:miri::interpreter: tmp2 = var0
    |   TRACE:miri::interpreter: tmp5 = var0
    |   TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |   TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |    TRACE:miri::interpreter: // bb0
    |    TRACE:miri::interpreter: var0 = arg0
    |    TRACE:miri::interpreter: tmp1 = var0
    |    TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |    TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |    TRACE:miri::interpreter: // bb3
    |    TRACE:miri::interpreter: tmp2 = var0
    |    TRACE:miri::interpreter: tmp5 = var0
    |    TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |    TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |    |TRACE:miri::interpreter: // bb0
    |    |TRACE:miri::interpreter: var0 = arg0
    |    |TRACE:miri::interpreter: tmp1 = var0
    |    |TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |    |TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |    |TRACE:miri::interpreter: // bb3
    |    |TRACE:miri::interpreter: tmp2 = var0
    |    |TRACE:miri::interpreter: tmp5 = var0
    |    |TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |    |TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |    | TRACE:miri::interpreter: // bb0
    |    | TRACE:miri::interpreter: var0 = arg0
    |    | TRACE:miri::interpreter: tmp1 = var0
    |    | TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |    | TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |    | TRACE:miri::interpreter: // bb3
    |    | TRACE:miri::interpreter: tmp2 = var0
    |    | TRACE:miri::interpreter: tmp5 = var0
    |    | TRACE:miri::interpreter: tmp4 = Sub(tmp5, const 1i64)
    |    | TRACE:miri::interpreter: tmp3 = factorial_recursive::fact(tmp4) -> bb4
    |    |  TRACE:miri::interpreter: // bb0
    |    |  TRACE:miri::interpreter: var0 = arg0
    |    |  TRACE:miri::interpreter: tmp1 = var0
    |    |  TRACE:miri::interpreter: tmp0 = Eq(tmp1, const 0i64)
    |    |  TRACE:miri::interpreter: if(tmp0) -> [true: bb2, false: bb3]
    |    |  TRACE:miri::interpreter: // bb2
    |    |  TRACE:miri::interpreter: return = const 1i64
    |    |  TRACE:miri::interpreter: goto -> bb1
    |    |  TRACE:miri::interpreter: // bb1
    |    |  TRACE:miri::interpreter: return
    |    | TRACE:miri::interpreter: // bb4
    |    | TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |    | TRACE:miri::interpreter: goto -> bb1
    |    | TRACE:miri::interpreter: // bb1
    |    | TRACE:miri::interpreter: return
    |    |TRACE:miri::interpreter: // bb4
    |    |TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |    |TRACE:miri::interpreter: goto -> bb1
    |    |TRACE:miri::interpreter: // bb1
    |    |TRACE:miri::interpreter: return
    |    TRACE:miri::interpreter: // bb4
    |    TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |    TRACE:miri::interpreter: goto -> bb1
    |    TRACE:miri::interpreter: // bb1
    |    TRACE:miri::interpreter: return
    |   TRACE:miri::interpreter: // bb4
    |   TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |   TRACE:miri::interpreter: goto -> bb1
    |   TRACE:miri::interpreter: // bb1
    |   TRACE:miri::interpreter: return
    |  TRACE:miri::interpreter: // bb4
    |  TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |  TRACE:miri::interpreter: goto -> bb1
    |  TRACE:miri::interpreter: // bb1
    |  TRACE:miri::interpreter: return
    | TRACE:miri::interpreter: // bb4
    | TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    | TRACE:miri::interpreter: goto -> bb1
    | TRACE:miri::interpreter: // bb1
    | TRACE:miri::interpreter: return
    |TRACE:miri::interpreter: // bb4
    |TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    |TRACE:miri::interpreter: goto -> bb1
    |TRACE:miri::interpreter: // bb1
    |TRACE:miri::interpreter: return
    TRACE:miri::interpreter: // bb4
    TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
    TRACE:miri::interpreter: goto -> bb1
    TRACE:miri::interpreter: // bb1
    TRACE:miri::interpreter: return
   TRACE:miri::interpreter: // bb4
   TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
   TRACE:miri::interpreter: goto -> bb1
   TRACE:miri::interpreter: // bb1
   TRACE:miri::interpreter: return
  TRACE:miri::interpreter: // bb4
  TRACE:miri::interpreter: return = Mul(tmp2, tmp3)
  TRACE:miri::interpreter: goto -> bb1
  TRACE:miri::interpreter: // bb1
  TRACE:miri::interpreter: return
 TRACE:miri::interpreter: // bb1
 TRACE:miri::interpreter: return

env_logger: Add config to Logger to allow changing the environmental variable, the default log level and the log format

#[macro_use]
extern crate log;
extern crate env_logger;
extern crate time;

use log::{LogRecord, LogLevelFilter};
use env_logger::LogConfig;

fn main() {
    let formatter = |record: &LogRecord| {
        let t = time::now();
        format!("{},{:03} - {} - {}",
            time::strftime("%Y-%m-%d %H:%M:%S", &t).unwrap(),
            t.tm_nsec / 1000_000,
            record.level(),
            record.args()
        )
    };

    let config = LogConfig {
        env_var: "RUST_LOGGER",
        format: Box::new(formatter),
        level: LogLevelFilter::Info,
    };

    env_logger::init_with_config(config).unwrap();

    error!("error message");
    info!("info message");
}

Adds key-value support to the log macros. Supersedes #346. Refs #343 #328. Thanks!

Syntax

femme::start(log::LevelFilter::Info).unwrap();
info!("hello");
info!("hello",);
info!("hello {}", "cats");
info!("hello {}", "cats",);
info!("hello {}", "cats", {
    cat_1: "chashu",
    cat_2: "nori",
});

Tasks

• [ ] write tests

Sometimes needs arise where one wants to deliver a custom logging statement to log crate. __log is exactly that function, but then anyone using it is risking breaking changes.

It seems to me once log API is considered stable, __log should be documented and stabilized as well.

This PR modifies log! and associated macros to disable logging at compile time for the Debug and Trace log levels when the debug_assertions option is disabled (which it is by default when optimizations are enabled).

The goal of this change is to make it easy to leave debug logging in place throughout a project and its dependencies, but to pay for it only in debug builds, and have it completely optimized out in release builds.

The log_level configuration option provides an existing way to do this. However, in practice there is no supported way to toggle log_level for a package and all of its dependencies when building with Cargo. However, Cargo does provide per-profile options for controlling rustc's built-in debug_assertions option. This option is a pretty good fit for debug logging, since it is intended to statically disable code that is useful for debugging but may have a performance cost. In fact, rustc's internal liblog already uses it this way for its debug! logging macro.

This PR is alternative to rust-lang/cargo#1948 which was closed by @alexcrichton in favor of “options that are local to the log crate itself.” Compared to the Cargo PR, this one is not as configurable, but does not require any external changes.

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?

I have an arm64 machine, and I'm trying to build a package that requires log.

Version: 0.4.17

error: failed to run custom build command for 'log v0.4.17'

Caused by:
  could not execute process '/tmp/cargo-installvKtAeG/release/build/log-b353450b8bd9d1bd/build-script-build' (never executed)

Caused by:
  Permission denied (os error 13)

(I assume this is an x86_64 executable that's being run, which obviously won't work on my machine)

Is there a possibility to use a created Log as an instance instead as in a global singlton style?

use simple_logger::SimpleLogger;

fn main() {
    let log = SimpleLogger::new().env().with_colors(true);
    log.warn!("This is an example message.");
}

Please impl Log for Vec<T> where T: Log, so that multiple parallel loggers can be set.

In my use case, I need to log in parallel to multiple loggers that are imported from different crates.

Hello!

I am implementing a custom logger that prints a JSON serialized struct. The struct has a field custom_list: Option<Vec<String>> that should be derived from log::kv::Value. However I could not figure out how to convert to Vec<String> from Value? Is that a missing feature or am I overseeing something here?

MyStruct {
   custom_list: Option<Vec<String>>
}

From end users perspective: info!(custom_list = as_serde!(vec!["a".to_string(), "b".to_string()]); "Test log msg");

Thanks

The comment on the Sync impl for AtomicUsize is:

// Any platform without atomics is unlikely to have multiple cores, so
// writing via Cell will not be a race condition.

While this may be true in practice, it's still technically incorrect and could open the door for bad codegen. Is there some background on why this impl is required even for platforms that don't support atomics?

Hello folks,

is it possible that I put a logline without a implicit newline at the end of the line? the macro log::info!() puts always a new line at the end. It would be nice if I had the possibility to distinguish it like the print! or println! macro it does!!!!