Initialize the env_logger in tests for tracing.

[Hoverbear]

Previously it required some manual intervention to get the logs of a test.

This makes it so, for example, RUST_LOG=raft=debug cargo test $SOME_TEST_NAME produces a full log.

[siddontang]

can we use one place to init the logger?
like TiKV CI does https://github.com/tikv/tikv/blob/master/tests/integrations.rs#L63

[Hoverbear]

In a CI you run a full test suite, this is targeted at users trying to trace/debug/log a single or regex'd test.

Once #52 is merged I think we should write the logs of each test to a folder and we can display them nicely when they fail.

[siddontang]

@Hoverbear

I don't think it is a good style to init logger everywhere. it looks weird.

[Hoverbear]

While I agree, it is the suggested style: https://github.com/sebasmagri/env_logger#in-tests

Regardless, there's no way not to have to init the logger ever test without relying on some test always being run first or something, which breaks cargo test $TEST workflows.

[siddontang]

em, do we need to use RUST_TEST_THREADS=1 for test now, seem that the log will be interleaved?

[Hoverbear]

@siddontang If you are debugging a specific test and have logging enabled, it's not a worry since it's only one test. If you're running the whole bank of tests then we won't log in them.

Later when we move to slog we can modify this so that logs for each test go into their own folder, and we can output failed tests.

[siddontang]

seem that tikv uses another way https://github.com/tikv/tikv/blob/master/ci-build/test.sh

can we use it yet? IMO, I still don't like adding the initialization to every test function. What we only to do is to output failed case log when CI fails.

If we want to trace by ourselves, I think we can add the initialization explicitly and run the test manually.

[Hoverbear]

@siddontang Unfortunately the testing system in Rust does not have a before_each type idea. So we need to do setup and teardown in every test right now. Sure we could do some fancy tricks with procedural macros or something, but those are kind of arcane. A simple setup() at the top of each test is nice and straightforward.

But we need to do initialization for things like fail-rs anyways if we use that in the future. What if I made a generic initialization function for tests to do logger/fail initialization etc?

I do not think developers should need to add dependencies (env_logger), import those dependencies, and introduce logging initialization into a test just to debug a failed test. I think getting the logs for a test should be easy.

[siddontang]

Got it. LGTM

PTAL @BusyJay

[Hoverbear]

@siddontang I will make this call an initializer function and place the env_logger stuff in it, so later we can just add to that function. I think it's a cleaner idea.

[siddontang]

Em @Hoverbear

I like your previous way, calling env logger initialization explictly. ☹️
If you want hide env logger, I prefer using a better name instead of test_init.

[overvenus]

LGTM

[BusyJay]

Why not keep it as a util function and call it when needed? It looks cumbersome to add it to every test case. And future test cases may probably forget to add the line.

[siddontang]

ping @Hoverbear

[Hoverbear]

@siddontang I'll rollback then.

[Hoverbear]

Ultimately we're discussing two things:

First, if we should enable the logger in tests or not.

I think in general, in any project, it is a good idea to be able to get the logs for a test without having to change code. I think this is something we can all agree on.

In a real situation the logger will be enabled, and since Raft is currently using log instead of slog any log calls when the logger is initialized and enabled via the RUST_LOG=raft=debug ENV variable will block until they can write.

This means that having the logger enabled could actually change the behavior of a complex high performance system (like TiKV before we used slog).

Second, we're discussing how to initialize the logger.

Since Rust doesn't provide some sort of before_each function, we must either look at crates to enable this, or use initializer/teardown functions. There is, for example, https://github.com/utkarshkukreti/speculate.rs/, however this would require some significant changes to the crate.

Introducing some initialization code to tests is much less invasive and is a good step towards using such a crate in the future if we do want it.

Currently we're using the direct call (adding let _ = env_logger::try_init()) because we'd rather not use an initialization function.

Right now, initializing the logger is just one line (let _ = env_logger::try_init()), but once we introduce slog, or use fail-rs in our tests this intialization will span multiple lines, so we will naturally extract this into a function.

Perhaps it is worthwhile to do this now, perhaps we will need to do this later.

Ultimately though, I think we will need to do this at some point in the future.

[siddontang]

do we need to close it now or merge it? @Hoverbear

[Hoverbear]

@siddontang If noone is opposed I will redo the work of extracting the log initializer to a function called setup_for_test() so we can easily extend in the future. Then we can merge it. Does that work for you?

[Hoverbear]

Ping @BusyJay @siddontang .

Are there any objections you have to this PR? I understand that we'd like a before_each but that doesn't' exist. This is the next best for now besides writing our own harness.

[breezewish]

LGTM. I'm afraid that this solution might be the simplest one available currently. See also rust-lang/rust#35762 If there are better solutions in future, we can adapt it.

[Hoverbear]

This has two LGTM so I'm merging now. Thanks. :)