Removing debug macros in Rust

Question

I'm writing an application that uses slog for logging multiple things during its execution. As such, I make extensive use of the info!, error!, warn! and debug! macros.

However, as expected, the debug! calls are there to help me debug the applications and I don't want those calls polluting the logs when actually using the application.

I've been trying to compile them away without success. This is the line I'm using: RUSTFLAGS="$RUSTFLAGS -C debug-assertions" cargo build --release

The compilation goes on smoothly, but on execution I see all the debug calls.

The following is a working example of my issue:

Cargo.toml:

[dependencies]
slog = { version = "1.5", features = ["max_level_trace", "release_max_level_warn"] }
slog-stream = "1.2.0"
slog-term = "1.5.0"
slog-json = "1.2.1"
slog-stdlog = "1.1.0"
log = "0.3.7"

main.rs:

#[macro_use]
extern crate slog;
extern crate slog_stream;
extern crate slog_term;
extern crate slog_json;
extern crate slog_stdlog;
#[macro_use]
extern crate log;

use std::path::Path;
use std::fs::OpenOptions;
use slog::DrainExt;

fn init_logger(work_dir : &Path) {
    let mut log_dir_buf = work_dir.to_path_buf();
    log_dir_buf.push("log");

    if !log_dir_buf.exists() {
        std::fs::create_dir(log_dir_buf.as_path()).unwrap();
    }

    log_dir_buf.push("the_log_file.log");
    let log_file_name = log_dir_buf.to_str().unwrap();

    let log_file = OpenOptions::new()
                        .create(true)
                        .write(true)
                        .truncate(true)
                        .open(log_file_name).unwrap();

    let console_drain = slog_term::streamer().build();
    let file_drain = slog_stream::stream(log_file, slog_json::default());
    let logger = slog::Logger::root(slog::duplicate(console_drain, file_drain).fuse(), o!());
    slog_stdlog::set_logger(logger).unwrap();
} 

fn main() {
    init_logger(Path::new("."));

    info!("This is an info message");
    warn!("This is a warn message");
    error!("This is an error message");
    debug!("This is a debug message");
}

Now, building a release version as stated above and running the binary I get the following output:

Jan 23 17:20:56.640 INFO This is an info message
Jan 23 17:20:56.641 WARN This is a warn message
Jan 23 17:20:56.641 ERRO This is an error message
Jan 23 17:20:56.641 DEBG This is a debug message

Finally, rust version: rustc 1.31.0 (abe02cefd 2018-12-04)

I know the version of slog I'm using is old, but upgrading the dependency is not a priority at the moment. However, the version's documentation states that log filtering should be possible as @shepmaster describes in the linked answer, it just doesn't seem to work for me. What am I missing?

Answer 1

In order to simplify the issue, I made another working example with the current version of slog (2.4.1) that set a global scope logger and the issue still reproduced. This is the code example:

extern crate slog;
extern crate slog_async;
extern crate slog_json;
extern crate slog_term;
extern crate slog_scope;
extern crate slog_stdlog;
#[macro_use]
extern crate log;

fn complex_logging() -> Result<(), log::SetLoggerError> {
    //Create the output file
    let log_path = "your_log_file_path.log";
    let file = OpenOptions::new()
        .create(true)
        .write(true)
        .truncate(true)
        .open(log_path)
        .unwrap();

    //Create the terminal drain
    let decorator = slog_term::TermDecorator::new().build();
    let d1 = slog_term::FullFormat::new(decorator).build().fuse();
    let d1 = slog_async::Async::new(d1).build().fuse();

    //Create the file drain
    let d2 = slog_json::Json::new(file)
        .add_default_keys()
        .build()
        .fuse();
    let d2 = slog_async::Async::new(d2).build().fuse();

    //Fuse the drains and create the logger
    let logger = slog::Logger::root(slog::Duplicate::new(d1, d2).fuse(), o!());
    let _guard = slog_scope::set_global_logger(logger);

    //register slog_stdlog as the log handler with the log crate
    slog_stdlog::init().unwrap();


    trace!("logging a trace message");
    debug!("debug values \"x\" => 1, \"y\" => -1");
    info!("some interesting info; where => right here");
    warn!("be cautious!; why => you never know...");
    error!("wrong, foobar; type => unknown");

    Ok(())
}

fn main() {
  let _res = complex_logging();    
}

Running the above example after building for release yields this result:

Jan 30 13:53:52.398 TRCE logging a trace message
Jan 30 13:53:52.399 DEBG debug values "x" => 1, "y" => -1
Jan 30 13:53:52.399 INFO some interesting info; where => right here
Jan 30 13:53:52.399 WARN be cautious!; why => you never know...
Jan 30 13:53:52.399 ERRO wrong, foobar; type => unknown

However, a new example that passes loggers around fixes the issue. Here's the working example:

#[macro_use]
extern crate slog;
extern crate slog_async;
extern crate slog_json;
extern crate slog_term;
extern crate slog_scope;
extern crate slog_stdlog;

use slog::Drain;
use std::fs::OpenOptions;
use std::io;
use std::sync::Mutex;

fn duplicate_log() {
    let plain = slog_term::PlainSyncDecorator::new(std::io::stdout());
    let d1 = slog_term::FullFormat::new(plain).build().fuse();
    let d2 = Mutex::new(slog_json::Json::default(io::stdout())).fuse();
    let log = slog::Logger::root(slog::Duplicate::new(d1, d2).fuse(), o!("version" => env!("CARGO_PKG_VERSION")));

    trace!(log, "logging a trace message");
    debug!(log, "debug values"; "x" => 1, "y" => -1);
    info!(log, "some interesting info"; "where" => "right here");
    warn!(log, "be cautious!"; "why" => "you never know...");
    error!(log, "wrong {}", "foobar"; "type" => "unknown");
    crit!(log, "abandoning test");
}

fn main() {
   duplicate_log();
}

Running the working example yields the following result:

Jan 30 13:56:30.839 INFO some interesting info, where: right here, version: 0.1.0
{"msg":"some interesting info","level":"INFO","ts":"2019-01-30T13:56:30.839762+00:00","version":"0.1.0","where":"right here"}
Jan 30 13:56:30.839 WARN be cautious!, why: you never know..., version: 0.1.0
{"msg":"be cautious!","level":"WARN","ts":"2019-01-30T13:56:30.839787+00:00","version":"0.1.0","why":"you never know..."}
Jan 30 13:56:30.839 ERRO wrong foobar, type: unknown, version: 0.1.0
{"msg":"wrong foobar","level":"ERRO","ts":"2019-01-30T13:56:30.839802+00:00","version":"0.1.0","type":"unknown"}
Jan 30 13:56:30.839 CRIT abandoning test, version: 0.1.0
{"msg":"abandoning test","level":"CRIT","ts":"2019-01-30T13:56:30.839815+00:00","version":"0.1.0"}

If you are running into a similar issue as I did, my problem was setting a global scope logger. Passing around loggers fixes this issue.

Answer 2

This link might be helpful in your situation.

According to the documentation linked above,

calls to debug! and trace! are only included in the program if debug-assertions=yes is turned on in config.toml

Have you checked your config.toml file to see if debug-assertions is set to yes?

Answer 3

The slog crate relies on the debug-assertions codegen option to distinguish between "release" builds and "debug" builds. Thus, by enabling debug-assertions (by passing -C debug-assertions to the compiler via RUSTFLAGS), slog doesn't take the release_max_level_* feature flags into account.

debug-assertions are disabled by default in release builds, so if you didn't mean to enable debug-assertions, simply don't pass that flag to the compiler. Note also that you can enable or disable debug-assertions via the [profile.*] sections in Cargo.toml.