Trying to figure out how to have a main logger that is passed down into components that based on their configuration set a LevelFilter. I can't get the drain from the drain from main log for LevelFilter::new and I don't want a new logger but the previous logger copied (but it doesn't take LevelFilter as Drain, only root does) ...

When writing unit tests, cargo captures output to stdout by default.

#[test]
fn print() {
    println!("Logging with println!");
}

This will not print the text to the terminal, unless cargo test is started with the -- --nocapture argument.

However, with slog this does not seem to work:

// main.rs

fn main() {
    println!("Hello, world!");
}

#[cfg(test)]
mod tests {
    use slog::{Drain, o, info};

    #[test]
    fn print() {
        println!("Logging with println!");
    }

    #[test]
    fn log_to_stdout() {
        let decorator = slog_term::TermDecorator::new().stdout().build();
        let drain = slog_term::CompactFormat::new(decorator).build();
        let log = slog::Logger::root(std::sync::Mutex::new(drain).fuse(), o!());
        info!(log, "Logging to stdout");
    }

    #[test]
    fn log_to_stderr() {
        let decorator = slog_term::TermDecorator::new().stderr().build();
        let drain = slog_term::CompactFormat::new(decorator).build();
        let log = slog::Logger::root(std::sync::Mutex::new(drain).fuse(), o!());
        info!(log, "Logging to stderr");
    }
}

Running this with cargo test will print:

$ cargo test -- --test-threads=1
    Finished test [unoptimized + debuginfo] target(s) in 0.02s
     Running target/debug/deps/asdf-5593e16ab0d57485

running 3 tests
test tests::log_to_stderr ... Feb 17 17:33:41.976 INFO Logging to stderr
ok
test tests::log_to_stdout ... Feb 17 17:33:41.977 INFO Logging to stdout
ok
test tests::print ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

Neither stdout nor stderr logs are captured.

I realize that this is probably due to some pecularity in how cargo handles capturing, but is there some kind of drain that logs in a cargo log capturing compatible way (possibly using println) that can be used in tests?

https://github.com/dpc/slog-rs/wiki/Bench-log

Ideas:

• [x] &'a str in RecordInfo`
• [x] static dispatch - 39e6b5e
• [x] measure perf of closure-values
• [x] stdlog not to allocate String
• [x] Arc chaining instead of copying in Logger hierarchies?
• [x] closure-values not to allocate anything - implement SerializeKey for Fn(&RecordInfo, mut io::Writer) ? so the value can output itself without returning?
• [x] use the same feature that standard log uses to remove logging statesments at compile time. Now that macros are being used, this should work smoothly.

Explicit support for std::error::Error

This change implements support for std::error::Error, which is a popular trait used for errors. Since people usually log errors, it makes sense to support them directly.

Changes include:

• Adding emit_error() method to Serializer
• Adding a default implementation for emit_error()
• Adding a helper wrapper struct for serializing foreign types that don't impl slog::Value but do impl std::error::Error
• Adding # prefix to macro, so that the wrapper can be instantiated easily
• Adding impl Value for std::io::Error
• Adding tests

Closes #273

Make sure to:

• [x] Add an entry to CHANGELOG.md (if neccessary)

This is a preview and the compatibility of # was not deeply inspected yet. I'm going to do it soon, just wanted to show my changes soon.

This also contains a commit fixing compilation of no_std tests.

I'm using IntelliJ Rust as an IDE and use slog. With IntelliJ Rust, completion usually works nicely for crates that I'm using.

The problem is that with slog, it doesn't work at all, e.g. for Logger. I can jump to the type using Navigate > Class..., and it will find it in the _logger.rs file of slog. But completion doesn't work and neither does jumping to the definition from a usage of Logger.

I'm pretty sure the reason for that is the use of the include! macro to include _logger.rs and co from lib.rs. I don't know if racer has the same problem.

Have you considered using normal mod logger and pub use logger::{a, b}? I know it's more to type, but maybe it's worth it to make completion work? It also has the advantage of making the whole API surface visible in one file.

I can also file an issue with IntelliJ Rust, but I wanted to file it here first because this is the only crates that I've encountered that uses this unusual way to define its API.

This commit bumps the minimum version from 1.15.0 to 1.26.1 which is a breaking change and it breaks builds for us which depend on 1.22.0 rust version.

One solution i to wrap the u128 support in an optional feature gate.

Now that 128 bit ints are stable, slog should probably add support for them. Not sure if this needs to be/can be gated on compiler version to avoid increasing the minimum required version.

Hi there, this is a screenshot of log output from my application: As you can see, the various Starting.../Finished. messages have different values for the middleware key.

Here's the same output in compact mode: Suddenly all the messages are grouped under the first middleware.

I've reviewed the slog/slog-term code to figure out how this can be and found this function that looks dubious to me: https://github.com/slog-rs/slog/blob/26d13bf2ace81c919f7b5280e6c8f5a506c84537/src/lib.rs#L659 The function returns the id for an OwnedKeyValueList, using the address of self as the id. Although I haven't confirmed it, I believe this is the source of my problem. Even if not, I believe it to be wrong anyway. The function ignores the fact that an OwnedKeyValueList could be dropped, and a new created in its place.

I believe this is what's happening in my case. I'm creating a new Logger with some additional data, use it to log some messages, then it falls off the stack and I create the next one. Since nothing really happens between the dropping of a Logger and the creation of the next one, it makes sense that they would all end up with the same address on the stack, causing all the OwnedKeyValueLists to have the same id.

I have this test program:

#[macro_use] extern crate log;
extern crate slog;
extern crate slog_envlogger;
extern crate slog_stdlog;
extern crate slog_term;

use slog::DrainExt;

fn main() {
    let drain = slog_term::StreamerBuilder::new().stderr().async().full().build();
    slog_stdlog::set_logger(slog::Logger::root(slog_envlogger::new(drain).ignore_err(),
                                               None)).unwrap();
    info!("exiting.");
}

compiled with these dependencies:

[dependencies]
log = "0.3"
slog = "1.5"
slog-envlogger = "0.5"
slog-stdlog = "1.1"
slog-term = "1.3"

If I run it with RUST_LOG=info set, I don't see the exiting. log line (at least, not consistently). I do if I remove the .async().

It looks like slog-async::AsyncCore (used internally by slog-term) has a Drop trait which flushes the async logger. But it's never run. A logger installed with slog_stdlog is never destroyed.

IMHO, the best solution to this would be for a logger to not be permanently async. Rather, when you install a logger, you get some handle which you can use to make it async in a scoped way. When leaving the scope, it flushes and reverts to sync, so log messages are never dropped.

 --> src/logging.rs:39:80
   |
39 |     let syslog_drain = slog_syslog::unix_3164(slog_syslog::Facility::LOG_USER).fuse();
   |                                                                                ^^^^
   |
   = note: the method `fuse` exists but the following trait bounds were not satisfied: `slog_syslog::Streamer3164 : slog::Drain`, `&slog_syslog::Streamer3164 : slog::Drain`, `&mut slog_syslog::Streamer3164 : slog::Drain`, `slog_syslog::Streamer3164 : std::iter::Iterator`

I've just started using slog and so far I'm really, really happy with it! I'm using it on a work project and have found structured logging a lot better than hand-crafted messages where you'll use string formatting to insert information.

One pattern I've started using is to implement KV for a struct so I can log its constituent parts. For example I might have a struct like this:

pub struct Config {
  width: f64,
  height: f64,
  start_point: StartPoint,
}

And then (without a KV impl) you might log the config details with something like debug!(logger, "Loaded Config"; "width" => cfg.width, ...);... Is this a common use case?

I'm thinking of prototyping a custom derive for KV in my own repo. If it goes anywhere, would you be interested in adding it to the slog-rs organisation?

I came across some puzzling behavior, where changing the order of a few lines when constructing the Logger in fn main can either work fine or cause major bugs.

this is a code snippet to illustrate the problem as simply as I can. there are three fn mains in example, the top one is causing problems and the bottom two (slight changes to order of operations) work fine.

#[macro_use]
extern crate slog;

use slog::Drain;

fn stdout_logger() -> slog::Logger {
    let decorator = slog_term::TermDecorator::new()
        .stdout()
        .build();
    let drain = slog_term::CompactFormat::new(decorator)
        .build()
        .fuse();
    let drain = slog_async::Async::new(drain)
        .chan_size(1024 * 64)
        .thread_name("my-logger".into())
        .build()
        .fuse();
    slog::Logger::root(drain, o!("version" => env!("CARGO_PKG_VERSION")))
}

// this one causes baffling behavior, including failures that are beyond just
// logging-related problems, ie function that is working in the other examples
// returns an error in this version instead.
fn main() {
    let logger = stdout_logger();
    let env_logger = env_logger::Logger::from_env(env_logger::Env::new().default_filter_or("debug"));
    rustwide::logging::init_with(env_logger);
    // ..
}

// this one works fine (emit a `debug!` log prior to the env_logger stuff)
fn main() {
    let logger = stdout_logger();
    debug!(logger, "initializing ...");
    let env_logger = env_logger::Logger::from_env(env_logger::Env::new().default_filter_or("debug"));
    rustwide::logging::init_with(env_logger);
    // ..
}

// this one also works fine (`logger` constructed following the env_logger stuff)
fn main() {
    let env_logger = env_logger::Logger::from_env(env_logger::Env::new().default_filter_or("debug"));
    rustwide::logging::init_with(env_logger);
    let logger = stdout_logger();
    // ..
}

Unfortunately, tracking and explaining what happens is somewhat complicated - this is a big program with tons going on in many threads. Also the behavior of the buggy version is very confusing. Not only do the logs not show up (which makes diagnosing what happened super difficult!), but the program also fails in terms of its non-logging-related output. i.e. a function that returns Ok(_) in the working versions returns Err(_) in the buggy one.

The part of the program that fails is on another thread from where the logger was originally constructed, also it is using a tokio runtime (which was constructed on the other thread), so there are possible async/tokio issues in play.

It likely occurs in a section of code where rustwide is actively capturing logs, but I don't know for sure (since I don't get any logs).

I get the same behavior with debug and release builds.

The rustwide::logging::init_with function is here. I haven't looked closely at what is going on there, but the code in that file is used to capture logs during sandboxed rust builds.

The reason I have both slog logger and the env_logger is because my code uses slog but some of the libraries are generating logs other ways that I would like to be able to view/capture.

do you guys have any kind of hypothetical theory for what might be behind this behavior? I am mostly interested in ensuring it doesn't happen (i.e. avoiding the buggy version). Seems this could possibly be the combination of overlapping global or thread local static values used to store state and macros that could paper-over type compatibility problems, but that's only a stab in the dark.

The title says it all, but there is an advisory for atty which is unmaintained, and this dependency likely needs to be replaced with something else. Advisory is here: https://rustsec.org/advisories/RUSTSEC-2021-0145.html

Thanks!

Could we make the code panic if the filtering is set to Trace despite Trace being disabled by flag?

I can't think of any situation where you'd want to disable Trace logging by feature but then configure a logger at Trace level, so presumably panicking in this situation wouldn't be bad.

Suggesting it after being bitten by the same "why aren't my trace logs appearing" issue noted in other issues.

I think rust generally gives up with formatting macros, but it seems like some function-style macros will be automatically formatted.

log!("message", "a"="b", "c"="something else") will actually be wrapped and spaced prettily (not sure what my formatter is, I'm using the rust analyzer vs code plugin). => seems to block the formatter.

It's easy to work around (just copy the macros and replace => with =), and it would be a breaking change if introduced to the library, but I thought I'd just bring it up for thought.

Totally unrelated, but I came here after looking at tracing and I'd much prefer slog. Tracing has tons of undocumented magic, and (AFAICT) the use of globals/thread locals to do the magic then leads to issues like using spans with async code, etc. The fact that you pass loggers around explicitly is a huge selling point for me.

Anyways, I really appreciate the project!

I noticed that Key is a type alias or a newtype depending on used features. This is a compatibility hazard.

For example:

Crate A:

serializer.emit_arguments("foo", &format_args!("bar"))

Crate B:

With featrue dynamic_keys

serializer.emit_arguments(Key::from(compute_key_string()), &format_args!("baz"))

Crate C depends on both A and B -> crate A will break.

One can defend against this by always using Key::from, but it's possible to forget and clippy complains about useless conversion. I think the best course of action is to use a newtype for static keys too. It will be breaking for crates that don't defend but it's probably more predictable and easier to handle than the situation above.

When tracing it's often useful to log various internal bytes such as messages being communicated. This adds emit_bytes method to make this easier and to possibly keep the type information.

Before I go on and work on this more, what do you think about adding this?

Make sure to:

• [ ] Add an entry to CHANGELOG.md (if neccessary)