Replace env_logger with sp_tracing

[AndreiEres]

Description of bug

env_logger working with gum seems to be skipping logs includes CandidateHash

Steps to reproduce

Minimal test case:

fn main() {
    env_logger::builder()
        .filter(None, log::LevelFilter::Info)
        .try_init()
        .unwrap();

    let a: i32 = 7;
    let hash = polkadot_primitives::Hash::repeat_byte(0xFA);
    let candidate_hash = polkadot_primitives::CandidateHash(hash);
    gum::info!(target: "bar", a, "xxx");
    gum::info!(target: "bar", a, ?hash, "xxx");
    gum::info!(target: "bar", a, ?hash, ?candidate_hash, "xxx");
}

Output:

[2024-05-31T12:03:56Z ERROR bar] xxx a=7
[2024-05-31T12:03:56Z INFO  bar] xxx a=7 hash=0xfafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafa

The third line with a candidate hash is absent.

What to do

We use env_logger only in tests, so it's better just to replace it with sp_tracing.

[alindima]

Have you tried using sp_tracing instead of env_logger? I've seen env_logger in subsystem-benchmarks omitting several logs for some reason

[AndreiEres]

This one works as expected, thank you.

fn main() {
    sp_tracing::init_for_tests();

    let a: i32 = 7;
    let hash = polkadot_primitives::Hash::repeat_byte(0xFA);
    let candidate_hash = polkadot_primitives::CandidateHash(hash);
    gum::info!(target: "bar", a, "xxx");
    gum::info!(target: "bar", a, ?hash, "xxx");
    gum::info!(target: "bar", a, ?hash, ?candidate_hash, "xxx");
}

2024-05-31T13:48:25.519985Z  INFO bar: xxx a=7
2024-05-31T13:48:25.520019Z  INFO bar: xxx a=7 hash=0xfafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafa
2024-05-31T13:48:25.520043Z  INFO bar: xxx a=7 hash=0xfafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafa candidate_hash=0xfafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafafa traceID=333610163647978885748406477874282560250

But what about env_logger. As I see we use it only in tests, maybe it's better to replace it with sp_tracing and add a note somewhere about this bug?

[alindima]

But what about env_logger. As I see we use it only in tests, maybe it's better to replace it with sp_tracing and add a note somewhere about this bug?

I agree it'd be good to replace env_logger with sp_tracing where possible. Not sure what's the root-cause of this bug (whether it's in gum or env_logger).

[AndreiEres]

Updated issue, seems like a good first one

[Safrout1]

I would like to take this on, I will start with doing the replacement in all test files, should it be replaced somewhere else?

[AndreiEres]

I would like to take this on, I will start with doing the replacement in all test files, should it be replaced somewhere else?

That's great! Let's start with tests but it would be great to understand where else we have it, maybe you can post a list here?

[Safrout1]

very very dumb question, what is the process to make a pull request here? is it a fork then a pull request from the fork? asking because I do not have permission to add a new branch here.

[AndreiEres]

@Safrout1 Yes, you have to do it over your own fork

[Safrout1]

@AndreiEres This is a draft pull request with one file only (for now), is this what we intend to do here, if yes, I will add all the other files: https://github.com/paritytech/polkadot-sdk/pull/5065

[Safrout1]

@AndreiEres I have updated the PR with all test files except for one: substrate/frame/contracts/src/tests.rs This one's tests fail when using sp-tracing, I think it has to do with setting the right env, I am still figuring it out. Let me know if the test is the wrong one in that case.

These files on the other hand are non-test files that use env_logger, let me know if those should be changed as well: 1 | bridges/relays/utils/src/initialize.rs 2 | polkadot/node/subsystem-bench/src/cli/subsystem-bench.rs 3 | substrate/client/executor/benches/bench.rs 4 | substrate/utils/frame/omni-bencher/src/main.rs